Async-profiler: Wall-clock profiling

[ksafonov]

It may be helpful to measure not only the time that method spent consuming the CPU but also the time method was waiting for lock or I/O. Please implement 'wall clock' profiling mode.

[nitsanw]

What you describe is the sort of thing implemented by instrumenting/tracing profilers. At this time async-profiler is a sampling profiler and AFAIK there's no intention to expand it's capabilities in the direction you describe (instrucmenting timestamps before/after method execution to provide time spent in each method).
Having said that async-profiler does lock profiling, and allocation profiling which both use tracepoints to instrument particular JVM Runtime events. There's certainly interest in tracing off-cpu time which can be done by tracing scheduler events and might be worth looking into.

[apangin]

Actually @ksafonov asked me about this feature and I've approved submitting this request, since there are definitely use cases that can benefit from wall-clock profiling. I'm also interested in this, for example, for profiling application start-up time.

I believe sampling profiler can solve this task to some extent. Basically, good old GetAllStackTraces can do the thing, though with a safepoint bias. I'm investigating how the similar functionality can be achieved without safepoint bias.

[nitsanw]

@apangin generically computing time in method for all methods is quite an invasive change to the program under test. I assume this is not on the cards here? maybe I just misunderstood what @ksafonov is after?

[apangin]

Certainly I'm not going to compute time spent in all methods in async-profiler. However, sampling techniques can be useful for wall-clock profiling, too. We just need to sample idle threads similarly to busy threads. That's what classic sampling profilers do.

I'm not sure if this matches original @ksafonov's intention, but this can definitely solve some scope of profiling problems.

[nitsanw]

If we want off CPU timing I think all the data we need should be in the data set:

1. Get stacks for all blocked threads
2. Trace schedule events throughout the profile period (can use current method of walking stack)
   This is a tracing style rather than sampling approach and I think is quite valuable.

[apangin]

I've added -e wall option in wall-clock branch. I'll be glad to get early feedback before the feature goes to main line.

[retronym]

There is a build failure on MacOS

$ make clean all
rm -rf build
mkdir -p build
g++ -O2 -D_XOPEN_SOURCE -D_DARWIN_C_SOURCE -DPROFILER_VERSION=\"1.5-ea\" -I/Users/jz/.jabba/jdk/1.8.172/Contents/Home/include -I/Users/jz/.jabba/jdk/1.8.172/Contents/Home/include/darwin -fPIC -shared -o build/libasyncProfiler.so src/*.cpp -ldl -lpthread
In file included from src/profiler.cpp:28:
src/wallClock.h:38:5: warning: control reaches end of non-void function [-Wreturn-type]
    }
    ^
1 warning generated.
src/wallClock.cpp:22:10: fatal error: 'sys/eventfd.h' file not found
#include <sys/eventfd.h>
         ^~~~~~~~~~~~~~~
1 error generated.
make: *** [build/libasyncProfiler.so] Error 1

$ uname -a
Darwin iMac2016.local 17.7.0 Darwin Kernel Version 17.7.0: Thu Jun 21 22:53:14 PDT 2018; root:xnu-4570.71.2~1/RELEASE_X86_64 x86_64

[apangin]

Yes, it works on Linux only right now. I'm investigating how to implement the similar functionality on macOS.

[calvin1978]

any update of this issue ?

we really want to profile which method costed most time, just like restful or db call.

[apangin]

@calvin1978 Have you tried a version from wall-clock branch? The feature is ready both on Linux and macOS. The feedback will help to integrate or improve the feature sooner.

[calvin1978]

@calvin1978 Have you tried a version from wall-clock branch? The feature is ready both on Linux and macOS. The feedback will help to integrate or improve the feature sooner.

ok, i will test it next week.

[calvin1978]

@apangin it works well in linux.

Can you add one more option to skip some famous methods which just waiting for incoming request, e.g.

java/util/concurrent/ThreadPoolExecutor.getTask
sun/nio/ch/EPollArrayWrapper.epollWait

these methods occupy too much space , and i remember that some other profiler will skip them.

[calvin1978]

./profiler.sh list 102788
Perf events:
cpu
page-faults
context-switches
cycles
instructions
cache-references
cache-misses
branches
branch-misses
bus-cycles
L1-dcache-load-misses
LLC-load-misses
dTLB-load-misses
mem:breakpoint
trace:tracepoint

Java events:
alloc
lock

wall didn't be listed in Java events.

[apangin]

@calvin1978 Thank you for the feedback. I'll take your comments into account.

[calvin1978]

let's skip the further request like omit "ThreadPoolExecutor.getTask", can you merge the branch back to master?

so i can build the snapshot with wall clock feature and also bug fix for clock profiling with JDK7 , we really need this two in our production environment.

[apangin]

@calvin1978 There are some architectural conflicts that need to be resolved before merging the branch into master. But I just did the reverse: synced wall-clock branch with current master.

[retronym]

I just took the latest wall-clock branch for a spin on MacOS to capture profiles of the Scala Compiler.

The full flame charts aren't super useful as they are dominated by the parked threads for JIT, GC, Finalizers, Reference Handlers, Thread Pools, etc.

But in my case, it's easy enough to grep for the entry points for the application under test. The reverse flame chart shows about 3% of time blocked in _res on opening and closing files for writing classfiles, 0.5% in pwrite writing to them.

Methodology and results:

https://drive.google.com/open?id=1f4hgHZwxVs0CyWey_v_9EfcfkqLyyz1p

The problem is, that after grepping for these "interesting" stacks I'm only left with a small number of samples (2128 for ~100s of execution). This suggests I should be telling async-profiler to choose a pre-filter the threads before sampling.

[apangin]

Thank you @retronym. The problem is understood. I could probably add a switch to exclude VM threads. Thread pools are not that simple though. They are not always idle, and it would be unfair to include only their running time - or this wouldn't be "wall-clock" mode anymore.
It's generally a good idea to run "wall-clock" profiling with -t option so that irrelevant threads could be easily grepped out afterwards.

[calvin1978]

@calvin1978 There are some architectural conflicts that need to be resolved before merging the branch into master. But I just did the reverse: synced wall-clock branch with current master.

thanks @apangin , so i can build a snapshot include all bug fixing use this branch , right ?

[apangin]

@calvin1978 Yes, you may proceed with this branch - now it contains all bugfixes from the upstream.

[oehme]

I just tried this out and this looks really promising! It would be great if one could exclude idle threads. Maybe not call that wall, but something different :) Looking at cpu alone can make you miss many problems (e.g. IO, blocking). Looking at wall includes all the idle threads that you can't really "make faster".

I'm happy to open a separate issue if that's preferable.

[apangin]

@oehme The problem is there are no "idle" threads in off-cpu profiling. Instead there are threads you are interested in and threads you are not interested in. Nobody knows how to distinguish one from another except yourself :)

For example, consider a thread waiting on a Condition object. This can be either an idle thread in some large ThreadPool, or a worker thread that can't proceed until a dependent task finishes. The stack traces will be the same, but in the former case this thread is irrelevant, while in the latter case this thread blocks execution of business logic. Similarly, a thread blocked on Socket.read may be completely irrelevant (e.g. when listening solely for a shutdown message) or this may be a thread waiting for an important response.

I believe it should be a user decision to choose which events or threads they are interested in. My intention was to provide some way to filter relevant threads or samples. I want to collect real use cases and suggestions: how would you like this filtering feature to be implemented in order to be useful in particular scenarios?

[oehme]

Right, looking at the profile it "looks obvious" that I wouldn't care about the GC thread waiting for stuff to do, but it's just waiting on a condition.

For my purposes it would probably be enough to be able to filter threads with a naming pattern or a thread group.

[apangin]

Thank you all for the feedback. I see that filtering is a must-have feature for wall-clock profiling to be useful. I created a separate issue for that: #187.

Besides that, -e wall mode is ready to use, so I'm closing the issue.

[ksafonov]

Just a stupid question: is the full-GC time included into wall time? I.e. if my thread is blocked on a lock for 5 ms, then there comes a 200-ms full GC pause, then my thread is sleeping for another 5ms, will I get 210 ms or 10 ms as the result?

[oehme]

All threads are profiled, that includes GC. However, profiling is not based on time, but samples.

[apangin]

@ksafonov It's an interesting question actually! It made me think of the aspects I haven't realized before.

1. Wall-clock profiler is still a sampling profiler. It does not show time spent inside a method, but the time can be estimated basing on the number of samples.
2. Sampler itself is not affected by GC, i.e. it produces signals in equal periods of time, no matter whether JVM runs garbage collection or not.
3. GC threads are sampled equally along with application threads.
4. The problem is JVM isn't ready to walk through Java stacks while GC is active. AsyncGetCallTrace API does not support that and returns an error in such cases.
5. Meanwhile profiler can still walk through native stacks, so you'll see a partial stack trace containing SafepointSynchronize::block(JavaThread*) or similar.
6. At the same time application threads are known to be at safepoint while GC is running, so it should be possible to obtain correct Java stack by other means. I've created #202 to address this issue.

[apangin]

UPDATE: Now Java stacks are displayed correctly during wall-clock profiling even when GC is active.