Qpid
  1. Qpid
  2. QPID-3236

Add high-resolution timestamps to log files for debug situations

    Details

    • Type: Task Task
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 0.11
    • Component/s: None
    • Labels:
      None

      Description

      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.

        Activity

        Hide
        Steve Huston added a comment -

        Good idea. I would like to see this enabled by a cmake setting, or the equivalent --enable-foo in autoconf.

        Show
        Steve Huston added a comment - Good idea. I would like to see this enabled by a cmake setting, or the equivalent --enable-foo in autoconf.
        Hide
        Kim van der Riet added a comment -

        The diff is located at https://reviews.apache.org/r/677/

        Comments welcome.

        Show
        Kim van der Riet added a comment - The diff is located at https://reviews.apache.org/r/677/ Comments welcome.
        Hide
        Kim van der Riet added a comment -

        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.

        Show
        Kim van der Riet added a comment - 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.
        Hide
        Kim van der Riet added a comment -

        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.

        Show
        Kim van der Riet added a comment - 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.
        Hide
        Kim van der Riet added a comment -

        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.

        Show
        Kim van der Riet added a comment - 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.
        Hide
        Kim van der Riet added a comment -

        Complete the Windows impl. of outputHiresNow() in Time.cpp.

        Show
        Kim van der Riet added a comment - Complete the Windows impl. of outputHiresNow() in Time.cpp.
        Hide
        Steve Huston added a comment -

        Windows code added in trunk r1100638.

        Show
        Steve Huston added a comment - Windows code added in trunk r1100638.
        Hide
        Chuck Rolke added a comment -

        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!

        Show
        Chuck Rolke added a comment - 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!

          People

          • Assignee:
            Steve Huston
            Reporter:
            Kim van der Riet
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development