giltene
commented
6 years ago The use of clocks can be seen in the source (e.g. https://github.com/giltene/jHiccup/blob/master/src/main/java/org/jhiccup/HiccupMeter.java#L470). It would be useful if you could include a few lines of the .hlog files around the problem area here (including a few lines before and after the 35s delta you mention). While hiccup-observation coverage is pretty good, it is not 100%. It is certainly possible (but unlikely) for a large freeze in execution to occur between the end of one measurement and the start of another, in a way that would not be captured as a hiccup, and cause a large gap in reporting times without an associated hiccup of similar magnitude being logged. e.g. at any point between line https://github.com/giltene/jHiccup/blob/master/src/main/java/org/jhiccup/HiccupMeter.java#L471 and the end of the loop.
The reasoning for originally preferring the current logic rather than more conservative one was that [originally] some potentially blocking synchronization was used between the hiccup recorder and the logging mechanism, and we did not want to incur potentially false-positive hiccup recordings due to synchronization (as opposed to an actual hiccup). However, since we've shifted to using of HdrHistogram's recorder mechanism (which guarantees wait-free behavior for the recording calls), we can probably expand timing coverage for the loop such that no hiccups could escape, without risking false positives due to synchronization. I'll consider making that change in future jHiccup versions.
jaj2276
isenberg
After chatting with an Azul engineer, it was suggested I create this issue to ask for a clarification in the documentation (if no code change is needed) to describe which clocks are being used when printing otu the log line and which clocks are being used to measure pauses (System.currentTimeMillis() and System.naonTime() respectively).
We have an issue (still unsolved at this point) where there was a 35s delta between two log lines (lines before and after are 1s apart). The maximum seen pause during this iteration was only 0.688 which wouldn't seem to be possible if the log line's clock showed a diff of 35s.