Best Practices for Interval Timing

[Patrick Noland]

Hi chromium java users,

On a recent CL the topic of which time source is best suited for various timing tasks came up. As it stands, we use three different time sources, at least on Android:

System.currentTImeMillis - non-monotonic wall time, millisecond resolution. We should probably never use this for interval timing ("the time may jump backwards or forwards unpredictably") but we still do in a few places, including some recently added code.

SystemClock.elapsedRealTime - monotonic wall time, millisecond resolution

SystemClock.elapsedRealTimeNanos - monotonic wall time, nanosecond resolution

As I see it, there are two issues with the current setup:

1) People are still using currentTImeMillis for interval timing

2) We only ever measure wall time

1) is explained sufficiently above but 2) is worth expanding on. If your thread of interest blocks for I/O or is preempted for stop the world GC, wall time will continue to advance, but the CPU isn't doing any work. Sometimes this is what you want to measure ("I care about the user-visible time it takes to fetch the data, de-serialize it, and render a widget") but sometimes it's not ("I want to know how computationally expensive this measure() call is"). 

For this reason, I think we should consider adopting SystemClock.currentThreadTimeMillis and Debug.threadCpuTimeNanos, which measure only single-threaded CPU time. If I understand correctly, the underlying time source for these functions, CLOCK_THREAD_CPUTIME_ID, is already used for measuring thread CPU time in TraceEvent. There is some inconsistency on what, if any, I/O time is counted by this clock; the android documentation for threadCpuTimeNanos states "The value returned indicates the amount of time that the current thread has spent executing code or waiting for certain types of I/O" but doesn't say which kinds of I/O. If I had to guess, it includes kernel time spent processing I/O but not actual time spent blocking.

Alongside this adoption maybe we should write a markdown file with formalized best practices for interval timing? It would describe when you'd want to use the various time sources. This could even become a class in base/ that implements the best practices and has descriptive function names.

My first attempt at the guidelines would go like so:

"I just want to spot check how long something takes locally; I don't need telemetry"

You can probably just use TraceEvent.

"I want to measure user visible time, including things like I/O and thread pre-emption"

Use SystemClock.elapsedRealTime for longer (>10ms) tasks and SystemClock.elapsedRealTimeNanos for shorter tasks.

"I want to measure elapsed CPU time for some potentially expensive operation, ignoring things like I/O and thread pre-emption"

Use currentThreadTimeMillis for longer (>10ms) tasks and threadCpuTimeNanos for shorter tasks.

Please let me know what you think, especially if you have more information about how the various clocks work or opinions about when they should be used.

[Ted Choc]

-internal mailing list

[Tommy Nyquist]

+ some people working on Perfetto / Chrometto: Do any of you have thoughts on how we should tackle this given the work in the Perfetto trace processor?

--
You received this message because you are subscribed to the Google Groups "java" group.
To unsubscribe from this group and stop receiving emails from it, send an email to java+uns...@chromium.org.
To view this discussion on the web visit https://groups.google.com/a/chromium.org/d/msgid/java/CAFs4gPqmRes9dgshJk88EJGJEpVSJRsJG3vhHVMsrFptNhxCfg%40mail.gmail.com.

[Tommy Nyquist]

Also, apologies for the delay in responding here. Hopefully with the people currently on this thread, we should be able to provide some solid guidance, and then I absolutely agree that this is something we could put in a markdown file.

[Primiano Tucci]

If what you are trying to answer is "what's a good default choice?" I would strongly advise *against* using CPU (process/thread) clocks, and just say: when in doubt use elapsedRealTimeNanos()/millis.

This is also aligned with what https://developer.android.com/reference/android/os/SystemClock says  "...so is the recommend basis for general purpose interval timing".

The problem with process/thread cpu time is that it can hide a lot of real problems, so you need to be 100% sure you really don't want to  measure them.

Here are some examples. Consider a CL that introduces a regression due to:

1. Hitting more frequently a highly contended mutex. Now every time a thread hits that code has a greater chance to get in a waiting queue.

2. Hitting a memory backed by a file-mapped mmap (e.g. assets on android) on the main thread. You'll block on I/O. 

3. Calling a framework API that under the hoods does synchronous binder transactions. Now you wait on system_server / gms to respond. 

4. Accidentally uses way more memory. Now every time you page fault the kernel will have to spend more time to reclaim memory from other processes and/or wait for them to be killed.

5. Getting into priority inversions because of a combination of the above (e.g. b/134045098)

My personal advice is:

One should use CLOCK_{PROCESS,THREAD}_CPUTIME_ID  clocks only when writing micro-benchmarks where the workload is known to be cpu bound (e.g. trying a different std::map<> implementation or the like), as a way to reduce noise.

In any other case where one is measuring some piece of code that might have impact on user experience, just stick with elapsedRealTimeNanos()

[Patrick Noland]

Thanks, that's really great information. Those are exactly the sort of concrete examples that I was hoping to find. Elapsed real time should definitely be the default choice, and any new documentation or /base/ timer code should make that clear.

FWIW this issue came up because I was reviewing code where we actually did want to micro-benchmark CPU-bound code and I realized there wasn't really a pre-built tool or documented best practice in Java for this sort of thing, just past examples of timing code sprinkled around the code base. Do you think that something like I proposed in the original message (a .md file and/or a base/ timer/clock class) would be worthwhile?

And do I understand correctly that the native tracing code actually measures and reports both elapsed real time and cpu time? And that the trace viewer displays them as "wall time" and "cpu time?"

Thanks!

To view this discussion on the web visit https://groups.google.com/a/chromium.org/d/msgid/java/CA%2ByH71eg4gz_fBOp_4qJwtjZ9Fm6roNfXOCDbp8OMjqZhRQbHA%40mail.gmail.com.

[Primiano Tucci]

On Mon, Feb 24, 2020 at 4:05 PM Patrick Noland <pno...@chromium.org> wrote:

Thanks, that's really great information. Those are exactly the sort of concrete examples that I was hoping to find. Elapsed real time should definitely be the default choice, and any new documentation or /base/ timer code should make that clear.

FWIW this issue came up because I was reviewing code where we actually did want to micro-benchmark CPU-bound code and I realized there wasn't really a pre-built tool or documented best practice in Java for this sort of thing, just past examples of timing code sprinkled around the code base. Do you think that something like I proposed in the original message (a .md file and/or a base/ timer/clock class) would be worthwhile?

And do I understand correctly that the native tracing code actually measures and reports both elapsed real time and cpu time? And that the trace viewer displays them as "wall time" and "cpu time?"

Trace captures both monotonic time and cpu time.

It monotonic time to compute the width of the slices, and uses cpu time to "colour" them, i.e. to give the extra information "out of xxx ns, this slice has been running on the cpu yyy/xxx ns"