Total execution time is the single most important metric by which we score geant4 and full_cms.

Since we would like to skip the whole initialization part of full_cms, we shoule trace from BeamOn() or even better from the EventManager::DoEventLoop(), because BeamOn() calls some initialization routines itself.

We use the following script:

As previous.

Trying to calculate the time that each functions consumes is troublesome. DTrace matches around 40,000 probes and the execution is slowed down considerably. If that option is chosen though, use vtimestamp instead of timestamp, so that the results are less affected by the DTrace itself.

Another, more pragmatic approach, is to identify those functions that contribute most in the overall execution time and focus on profiling them only. This can be done by taking sample stack traces, while full_cms is running. Then, we examine those stack traces and deduce which functions are the "hottest" (a function that is taking a lot time to execute, is more likely to get sampled, since we are sampling at a fixed rate).

More information can be found here. E.g.,

For 10 events the above invocation produces approximately 3MB of profiling data.

This is an example of the svg output file, and this is with demangled names.

After having identified the "hot" functions, we run a shell script that generates a DTrace script that focuses on profiling these functions only.

Example of DTrace script:

The script should be called with -Z (for not failing on unmathced probes) and with -x dynvarsize=8m (for not dropping dynamic variables). E.g.,

Example of DTrace output:

We let the full_cms run for 100 events and every time one such event is processed, we print the average time spent on the "hot" functions. The idea is to see past which event region the average times enter a steady state. We do this by enabling a probe, like the following:

An example can be found here. We, then, use a script file to extract the aggregations for every event, and another one, to reconstruct a time series for every "hot" function.

Complementary, we generate separate plots for each one of the traced functions, with the use of this script. Sample output can be found either in the form of a picassa web album or as a plain directory listing.

Solaris has two utilities for examining hardware performance counters: cpustat(1M) for overall system monitoring, and cputrack(1) for monitoring a process (or a family of them). With the help of this script, we can measure the cycles per instruction (CPI) of the full_cms experiment during its lifetime. For example:

A file with the full results from a complete simulation of the bench1_100.g4 may be found here. The data can be then plotted with this script, and the output image looks like this. Putting it all together:

The part of the plot where the CPI peaks is most likely contributed by the initialization of full_cms. As we, assumingly, enter the actual simulation and start processing events, CPI drops and stabilizes at _1.2. The plot also shows the ideal CPI ratio for a tight cpu-bounded application, which is 0.3-4 given that amd64 tries to execute 3 instructions per cycle.

Rule of thumb: Low CPI: we are cpu-bounded, High CPI: we are memory-bounded (cache misses?).

References: AMD64 PICs, CPI, by Brendan Gregg

There is a DTrace module that allows us to access the CPU hardware counters from within a DTrace script. We could use that to get live stack traces when the CPI goes beyond some threshold, identifying the exact code paths that worth optimizing. Unfortunately, in amd64 CPU architecture one cannot access more than 1 hardware counter, and consequently cannot calculate the CPI ratio. Instead, we measure the cache misses which are a major contributor to the CPI ratio. We do that as following:

Everytime full_cms hits 10000 L2 data cache misses, we acquire the current userspace stack trace. We then proceed as previous to generate a flamegraph with the greatest offenders in terms of L2 cache misses. It is shown that approximately half of the cache misses originate from the initialization code (GDML + xerces-c).

Similar analysis for Instruction Cache misses.

Similar to how we gather and plot CPI statistics, we can do the same with the Data Cache misses and Instruction Cache misses. For Instruction Cache misses:

[script] [plot]

or, for Data Cache misses:

[script] [plot]

In order for our measurements to be unbiased we need to flush the CPU caches everytime we start a new profiling cycle. Otherwise, we may get an artificially improved hits/miss ratio. There is an instruction, wbinvd, (write back and invalidate cache), that flushes both the L1 (internal) and L2 (external) caches, but requires to be called from kernel context. DTrace cannot be used here, since it was designed to disallow arbitrary code execution in kernel, whereas SystemTap is more liberal in nature and may be an option in Linux systems.

For Solaris, I used the dummy skeleton device driver, to issue the wbinvd instruction. How to build:

How to make sure that the wbinvd instruction has not been optimized out for whatever reason:

There were some concerns whether the combination of the cpc provider and the flamegraph approach for visualizing the CPU cache misses was valid. I.e., whether functions appearing to be causing many cache misses, were indeed causing many cache misses.

To dismiss any doubts, I decided to take some random Geant4 function and make it invalidate the CPU caches on purpose, every time it was called. I would then regenerate the flamegraph and compare it with one from the untainted version of the function.

The G4PropagatorInField::ComputeStep() function did not cause many (data) cache misses (<2% of total), so it seemed like a good candidate.

The first idea was to do something like the following:

Everytime the function would get called, it would cat(1) to our specially crafted dummy device driver and that would cause the CPU caches to get flushed. Unfortunately, all the "cat(1)'s" occur once per switchrate, which is around 1 sec by default. Also, the cat(1) happens in userspace when dtrace(1M) periodically claims its buffers. Therefore this would not give valid results, since the function call and the invalidation of CPU caches would be significantly dissociated timewise.

For the above reasons, we decided to pursue another route. DTrace has a built-in function, named rand() that returns a pseudo-number generator. This function can be used in constructs like this:

After the G4PropagatorInField::ComputeStep() function is called, DTrace executes rand() and iff the condition rand() % 101 == 0 is met, the code that resides inside the block is executed. Therefore the function call and rand() call happen very close in time. What we did was to replace the "genuine" version of rand() with another one that called wbinvd. We achieved that by rewriting kernel instructions with live patching. The rand() function is implemented as:

So, locating it inside dtrace_dif_subr was easy (0x1b0963 is the hex representation of 1771875):

We then replaced the idivq instruction, which occupied 3 bytes, with a nop (90) and wbinvd (0F 09):

We disassembled the result, just to make sure that everything went as planned:

To summarize, the reasons why we chose to hack rand() are:

Finally, we ran the profiling as previously:

We subsequently regenerated the flamegraph and confirmed that DTrace identified the increase in the CPU cache misses. Here is the graph with the unaltered ComputeStep function and this is the regenerated graph with the altered function.

The same exact analysis have been performed for G4VoxelNavigation::LocateNextVoxel(). The unaltered function and the regenerated graph with the altered function.

Special thanks to Sean Silva for his insights.

It has been brought to our attention that the graphs for CPI, DC/IC misses, etc had lots of outliers. We hypothesized that this could be an artifact imposed by the scheduler and/or other actions of the host operating system. For this reason we made the full_cms bind to a specific cpu (other than #0) during its lifetime. The command that we used was pbind(1M) in Solaris. After that the vast majority of the outliers has been disappeared.

This is an artifact caused by a compiler optimization, known as tail-call elimination or tail-call optimization. This type of optimization (which happens by default in g++ at the -O2 optimization level), happens when a function A() calls function C() as its last action. E.g.

In that case, the generated code is not this (pseudo-assembly):

but this:

The benefit, in terms of performance, is that we don’t setup a new stack trace for the function that is about to be called. The drawback is that we lose potentially useful information for debugging and profiling. A typical example can be found in the ProcessOneEvent() function. In the source code there exists this sequence of function calls: DoEventLoop() → ProcessOneEvent() → DoProcessing() → …

In the generated leafgraphs though, DoProcessing() appears to be a direct descendant node of DoEventLoop(), with ProcessOneEvent() not appearing at all. In the disassembled code:

As we can see, instead of a call/ret to G4EventManager::DoProcessing() there is instead a jmp instruction. Which is the reason why DTrace appears to be missing the ProcessOneEvent() (since its stack-frame is being taken by DoProcessing().

In continuation of the above, in order to precisely measure the time spent in ProcessOneEvent(), we need to follow the execution to DoProcessing() and find the address where it ret'urns. We do so by disassemblying DoProcessing(). We then supply that address as the return point to DTrace, which can probe arbitrary addresses, as shown below: