You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@qpid.apache.org by "Kim van der Riet (JIRA)" <ji...@apache.org> on 2011/04/29 16:30:03 UTC
[jira] [Created] (QPID-3236) Add high-resolution timestamps to log
files for debug situations
Add high-resolution timestamps to log files for debug situations
----------------------------------------------------------------
Key: QPID-3236
URL: https://issues.apache.org/jira/browse/QPID-3236
Project: Qpid
Issue Type: Task
Reporter: Kim van der Riet
Assignee: Kim van der Riet
In some performance-related debug situations, it would be useful to see the time between logged events (in debug or trace mode). However, the standard log timestamp has a 1 second resolution, and it does not help matters when hundreds of events of interest all occur within the same second.
I propose to add a #define in qpid/sys/posix/Time.cpp which would change the timestamp printed by the outputFormattedNow() method to an unformatted second/nanosecond output. This define would be uncommented and compiled in when needed, but remain commented out for normal use. A comment would explain its use.
I am sure an equivalent change could also be made to the windows version in qpid/sys/windows/Time.cpp.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project: http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org
[jira] [Commented] (QPID-3236) Add high-resolution timestamps to
log files for debug situations
Posted by "Chuck Rolke (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/QPID-3236?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13030569#comment-13030569 ]
Chuck Rolke commented on QPID-3236:
-----------------------------------
My solution to the Windows impl is identical to Steve's with the addition of adding a suffix indicating the processor number on which the performance query was executed. As long as all the counts are done on the same CPU then the TOD results correlate perfectly. Some BIOSs have a differing CPU tick count between CPUs that may make uS comparisons a little off. Examples from web show actually changing the execution of the thread back to the original CPU to get a valid, comparable tick count but to me this is excessive.
Ship it!
> Add high-resolution timestamps to log files for debug situations
> ----------------------------------------------------------------
>
> Key: QPID-3236
> URL: https://issues.apache.org/jira/browse/QPID-3236
> Project: Qpid
> Issue Type: Task
> Reporter: Kim van der Riet
> Assignee: Steve Huston
> Fix For: 0.11
>
>
> In some performance-related debug situations, it would be useful to see the time between logged events (in debug or trace mode). However, the standard log timestamp has a 1 second resolution, and it does not help matters when hundreds of events of interest all occur within the same second.
> I propose to add a #define in qpid/sys/posix/Time.cpp which would change the timestamp printed by the outputFormattedNow() method to an unformatted second/nanosecond output. This define would be uncommented and compiled in when needed, but remain commented out for normal use. A comment would explain its use.
> I am sure an equivalent change could also be made to the windows version in qpid/sys/windows/Time.cpp.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project: http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org
[jira] [Commented] (QPID-3236) Add high-resolution timestamps to
log files for debug situations
Posted by "Kim van der Riet (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/QPID-3236?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13026994#comment-13026994 ]
Kim van der Riet commented on QPID-3236:
----------------------------------------
The diff is located at https://reviews.apache.org/r/677/
Comments welcome.
> Add high-resolution timestamps to log files for debug situations
> ----------------------------------------------------------------
>
> Key: QPID-3236
> URL: https://issues.apache.org/jira/browse/QPID-3236
> Project: Qpid
> Issue Type: Task
> Reporter: Kim van der Riet
> Assignee: Kim van der Riet
>
> In some performance-related debug situations, it would be useful to see the time between logged events (in debug or trace mode). However, the standard log timestamp has a 1 second resolution, and it does not help matters when hundreds of events of interest all occur within the same second.
> I propose to add a #define in qpid/sys/posix/Time.cpp which would change the timestamp printed by the outputFormattedNow() method to an unformatted second/nanosecond output. This define would be uncommented and compiled in when needed, but remain commented out for normal use. A comment would explain its use.
> I am sure an equivalent change could also be made to the windows version in qpid/sys/windows/Time.cpp.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project: http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org
[jira] [Resolved] (QPID-3236) Add high-resolution timestamps to log
files for debug situations
Posted by "Steve Huston (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/QPID-3236?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Steve Huston resolved QPID-3236.
--------------------------------
Resolution: Fixed
Fix Version/s: 0.11
Windows code added in trunk r1100638.
> Add high-resolution timestamps to log files for debug situations
> ----------------------------------------------------------------
>
> Key: QPID-3236
> URL: https://issues.apache.org/jira/browse/QPID-3236
> Project: Qpid
> Issue Type: Task
> Reporter: Kim van der Riet
> Assignee: Steve Huston
> Fix For: 0.11
>
>
> In some performance-related debug situations, it would be useful to see the time between logged events (in debug or trace mode). However, the standard log timestamp has a 1 second resolution, and it does not help matters when hundreds of events of interest all occur within the same second.
> I propose to add a #define in qpid/sys/posix/Time.cpp which would change the timestamp printed by the outputFormattedNow() method to an unformatted second/nanosecond output. This define would be uncommented and compiled in when needed, but remain commented out for normal use. A comment would explain its use.
> I am sure an equivalent change could also be made to the windows version in qpid/sys/windows/Time.cpp.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project: http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org
[jira] [Commented] (QPID-3236) Add high-resolution timestamps to
log files for debug situations
Posted by "Kim van der Riet (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/QPID-3236?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13026996#comment-13026996 ]
Kim van der Riet commented on QPID-3236:
----------------------------------------
Adding options to autoconf and cmake is an excellent idea! My diff does not have these, but as it is a matter of enabling a well-known define, this should be relatively trivial.
> Add high-resolution timestamps to log files for debug situations
> ----------------------------------------------------------------
>
> Key: QPID-3236
> URL: https://issues.apache.org/jira/browse/QPID-3236
> Project: Qpid
> Issue Type: Task
> Reporter: Kim van der Riet
> Assignee: Kim van der Riet
>
> In some performance-related debug situations, it would be useful to see the time between logged events (in debug or trace mode). However, the standard log timestamp has a 1 second resolution, and it does not help matters when hundreds of events of interest all occur within the same second.
> I propose to add a #define in qpid/sys/posix/Time.cpp which would change the timestamp printed by the outputFormattedNow() method to an unformatted second/nanosecond output. This define would be uncommented and compiled in when needed, but remain commented out for normal use. A comment would explain its use.
> I am sure an equivalent change could also be made to the windows version in qpid/sys/windows/Time.cpp.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project: http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org
[jira] [Commented] (QPID-3236) Add high-resolution timestamps to
log files for debug situations
Posted by "Kim van der Riet (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/QPID-3236?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13027648#comment-13027648 ]
Kim van der Riet commented on QPID-3236:
----------------------------------------
Checked in as r.1098554.
The Windows code has a stub only - should compile, but will print "XXXXXXXXX.XXXXXXXXXs " as the timestamp. I'll leave the task open and reassign to Steve to complete the Windows part.
> Add high-resolution timestamps to log files for debug situations
> ----------------------------------------------------------------
>
> Key: QPID-3236
> URL: https://issues.apache.org/jira/browse/QPID-3236
> Project: Qpid
> Issue Type: Task
> Reporter: Kim van der Riet
> Assignee: Kim van der Riet
>
> In some performance-related debug situations, it would be useful to see the time between logged events (in debug or trace mode). However, the standard log timestamp has a 1 second resolution, and it does not help matters when hundreds of events of interest all occur within the same second.
> I propose to add a #define in qpid/sys/posix/Time.cpp which would change the timestamp printed by the outputFormattedNow() method to an unformatted second/nanosecond output. This define would be uncommented and compiled in when needed, but remain commented out for normal use. A comment would explain its use.
> I am sure an equivalent change could also be made to the windows version in qpid/sys/windows/Time.cpp.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project: http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org
[jira] [Assigned] (QPID-3236) Add high-resolution timestamps to log
files for debug situations
Posted by "Kim van der Riet (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/QPID-3236?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Kim van der Riet reassigned QPID-3236:
--------------------------------------
Assignee: Steve Huston (was: Kim van der Riet)
Complete the Windows impl. of outputHiresNow() in Time.cpp.
> Add high-resolution timestamps to log files for debug situations
> ----------------------------------------------------------------
>
> Key: QPID-3236
> URL: https://issues.apache.org/jira/browse/QPID-3236
> Project: Qpid
> Issue Type: Task
> Reporter: Kim van der Riet
> Assignee: Steve Huston
>
> In some performance-related debug situations, it would be useful to see the time between logged events (in debug or trace mode). However, the standard log timestamp has a 1 second resolution, and it does not help matters when hundreds of events of interest all occur within the same second.
> I propose to add a #define in qpid/sys/posix/Time.cpp which would change the timestamp printed by the outputFormattedNow() method to an unformatted second/nanosecond output. This define would be uncommented and compiled in when needed, but remain commented out for normal use. A comment would explain its use.
> I am sure an equivalent change could also be made to the windows version in qpid/sys/windows/Time.cpp.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project: http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org
[jira] [Commented] (QPID-3236) Add high-resolution timestamps to
log files for debug situations
Posted by "Kim van der Riet (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/QPID-3236?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13027644#comment-13027644 ]
Kim van der Riet commented on QPID-3236:
----------------------------------------
For completeness, the following comments were given in ReviewBoard:
----
Description:
This change allows unformatted high-resolution timestamps to replace the normal 1-second resolution formatted date/time timestamps in the log files for debug situations where looking at the elapsed time between events might be useful. If many events occur within the same second, then the standard resolution timestamps are unhelpful. The idea is to uncomment the #define and compile in the high-res timestamps when needed, but to leave the #define commented out for normal use.
See https://issues.apache.org/jira/browse/QPID-3236
Comments welcome.
----
Kenneth Giusti:
<Ship it!>
Ahhh - where was this last week when I could've really used it? Good idea!
----
Alan Conway:
Why not make this a runtime option enabled with --log-highres-timestamp? The cost of a simple "if (highresTimestampsEnabled)" isn't high compared to all the formatting. Then this could be turned on without a rebuild, so could be used by consultants in the field etc.
----
Steve Huston:
I replied in the JIRA that the compile-time switch should be set in cmake/autoconf, but I like Alan's run-time idea more. However, I think it would be better if the run-time decision was made at the caller of this (call a high-res formatted time rather than the regular one). Then it would be immediately clear if a platform forgets to define the high-res code - it would break at build time - and the decision is made in platform-neutral code so it's always uniform in the documentation and run-time handling.
----
Kim van der Riet:
<Added new patch>
Thanks for the comments. Here is a version that defines a logging option --log-hires-timestamp, and behaves as follows:
./qpidd --auth no --log-enable info+ --log-hires-timestamp yes
1304105003.833914147s info Management enabled
1304105003.834060811s info ManagementAgent restored broker ID: 07133ede-bda4-4c3f-a649-e39007c83e98
1304105003.834542359s notice SASL disabled: No Authentication Performed
1304105003.834659341s notice Listening on TCP port 5672
1304105003.834785542s notice Broker running
^C1304105017.576632384s notice Shut down
As Steve suggested, the function that formats this version is a separate function outputHiresNow(). Steve, I have not added this to the windows version, but I assume that it will work the same as it uses only std::ostream and iomanip functions. Can you verify?
----
Alan Conway:
<Ship it!>
----
Steve Huston:
<Ship it!>
I like it. Nice work.
If someone can plug in the Windows code, that would be great! I'm not going to be able to get to it until at least next Tuesday.
> Add high-resolution timestamps to log files for debug situations
> ----------------------------------------------------------------
>
> Key: QPID-3236
> URL: https://issues.apache.org/jira/browse/QPID-3236
> Project: Qpid
> Issue Type: Task
> Reporter: Kim van der Riet
> Assignee: Kim van der Riet
>
> In some performance-related debug situations, it would be useful to see the time between logged events (in debug or trace mode). However, the standard log timestamp has a 1 second resolution, and it does not help matters when hundreds of events of interest all occur within the same second.
> I propose to add a #define in qpid/sys/posix/Time.cpp which would change the timestamp printed by the outputFormattedNow() method to an unformatted second/nanosecond output. This define would be uncommented and compiled in when needed, but remain commented out for normal use. A comment would explain its use.
> I am sure an equivalent change could also be made to the windows version in qpid/sys/windows/Time.cpp.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project: http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org
[jira] [Commented] (QPID-3236) Add high-resolution timestamps to
log files for debug situations
Posted by "Steve Huston (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/QPID-3236?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13026992#comment-13026992 ]
Steve Huston commented on QPID-3236:
------------------------------------
Good idea. I would like to see this enabled by a cmake setting, or the equivalent --enable-foo in autoconf.
> Add high-resolution timestamps to log files for debug situations
> ----------------------------------------------------------------
>
> Key: QPID-3236
> URL: https://issues.apache.org/jira/browse/QPID-3236
> Project: Qpid
> Issue Type: Task
> Reporter: Kim van der Riet
> Assignee: Kim van der Riet
>
> In some performance-related debug situations, it would be useful to see the time between logged events (in debug or trace mode). However, the standard log timestamp has a 1 second resolution, and it does not help matters when hundreds of events of interest all occur within the same second.
> I propose to add a #define in qpid/sys/posix/Time.cpp which would change the timestamp printed by the outputFormattedNow() method to an unformatted second/nanosecond output. This define would be uncommented and compiled in when needed, but remain commented out for normal use. A comment would explain its use.
> I am sure an equivalent change could also be made to the windows version in qpid/sys/windows/Time.cpp.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project: http://qpid.apache.org
Use/Interact: mailto:dev-subscribe@qpid.apache.org