Microsecond values logged for transactions can overflow

XMLWordPrintableJSON

    • Type: Bug
    • Resolution: Unresolved
    • Priority: Major - P3
    • None
    • Affects Version/s: None
    • Component/s: None
    • Replication
    • ALL
    • None
    • 3
    • TBD
    • None
    • None
    • None
    • None
    • None
    • None
    • None

      Transaction duration is tracked in milliseconds. However, the active time for a transaction is tracked in microseconds, and we also derive an inactive time in microseconds by taking the difference of those two values.

      However, it appears there are some cases possible in the wild where we cannot represent one of these microsecond durations with a 32-bit integer. For example, we saw a situation where the following was logged:

      "timeActiveMicros":126853,"timeInactiveMicros":-505909924,"durationMillis":3789184

      This is an unusually long transaction duration. That duration itself, when converted to microseconds, cannot be represented as an Int32, nor can the derived timeInactiveMicros. 

      Where and why in the code that conversion to Int32 occurs, I've not found yet. It may be something that happens implicitly in the logging infrastructure. But I am confident that it is an overflow issue because of how perfectly the numbers match up –  

      3789184 ms is ~3789184000 microseconds. (Approximate as the ms value is likely rounded). Subtracting the active time gives 3789057147 microseconds. Converted to an Int32, that overflows to -505910149. This is just slightly off from the logged value, by 225 microseconds, which is accounted for by the ms duration having been rounded. 

              Assignee:
              Unassigned
              Reporter:
              Kaitlin Mahar
              Votes:
              0 Vote for this issue
              Watchers:
              9 Start watching this issue

                Created:
                Updated: