Nested timers by marvinKaster · Pull Request #2486 · arbor-sim/arbor

marvinKaster · 2025-11-27T14:06:14Z

Introducing nested timers. You can now create timed sections within other timed sections. The spent time will be outputted in a hierarchical format.

Code example

PE(first_timer);
//...
PE(second_timer);
//...
PL(second_timer);
//...
PL(first_timer);

Example output of the ring benchmark

REGION                         CALLS       WALL    WALLCHILDS    WALLCAPTURED%    THREAD        %    
arbor                              2    285.048       285.129            100.0    35.631    100.0    
  run                              0    279.246       273.738             98.0    34.906     98.0    
    update                       199    273.264       218.751             80.1    34.158     95.9    
      advance                  19999    218.640       218.333             99.9    27.330     76.7    
        integrate              19999    218.067       135.328             62.1    27.258     76.5    
          cable              3999999     55.818         0.000              0.0     6.977     19.6    
          current_pas        3999999     24.780         0.000              0.0     3.098      8.7    
          ionupdate          3999999      6.131         0.000              0.0     0.766      2.2    
          zero               3999999      5.964         0.000              0.0     0.745      2.1    
          state_hh           3999999      5.259         0.000              0.0     0.657      1.8    
          threshold          3999999      5.157         0.000              0.0     0.645      1.8    
          samples            3999999      4.836         0.000              0.0     0.604      1.7    
          stimuli            3999999      4.567         0.000              0.0     0.571      1.6    
          current_expsyn     3999999      4.297         0.000              0.0     0.537      1.5    
          current_hh         3999999      4.189         0.000              0.0     0.524      1.5    
          state_expsyn       3999999      4.132         0.000              0.0     0.517      1.4    
          state_pas          3999999      3.698         0.000              0.0     0.462      1.3    
          post               3999999      3.518         0.000              0.0     0.440      1.2    
          setup                19999      2.981         0.000              0.0     0.373      1.0    
          event_expsyn            93      0.000         0.000              0.0     0.000      0.0    
        clear                  19999      0.134         0.000              0.0     0.017      0.0    
        sampledeliver          19999      0.099         0.000              0.0     0.012      0.0    
        samplesetup            19999      0.034         0.000              0.0     0.004      0.0    
      spikes                   19999      0.111         0.000              0.0     0.014      0.0    
    enqueue                    19999      0.458         0.354             77.3     0.057      0.2    
      merge_cell_events        19999      0.306         0.123             40.2     0.038      0.1    
        reserve                19999      0.031         0.000              0.0     0.004      0.0    
        tree                   19999      0.029         0.000              0.0     0.004      0.0    
        setup                  19999      0.022         0.000              0.0     0.003      0.0    
        generators             19999      0.022         0.000              0.0     0.003      0.0    
        push_back              19999      0.019         0.000              0.0     0.002      0.0    
      sort                     19999      0.026         0.000              0.0     0.003      0.0    
      clear                    19999      0.022         0.000              0.0     0.003      0.0    
    exchange                     199      0.016         0.013             81.4     0.002      0.0    
      exchange                   199      0.008         0.006             79.5     0.001      0.0    
        gather                   199      0.005         0.000              0.0     0.001      0.0    
        sort                     199      0.001         0.000              0.0     0.000      0.0    
        remote                   199      0.000         0.000              0.0     0.000      0.0    
        post_process             199      0.000         0.000              0.0     0.000      0.0    
      walkspikes                 199      0.003         0.000              0.0     0.000      0.0    
      gatherlocal                199      0.001         0.000              0.0     0.000      0.0    
      spikeio                    199      0.001         0.000              0.0     0.000      0.0    
  init                             0      5.882         5.883            100.0     0.735      2.1    
    group                          0      5.881         5.716             97.2     0.735      2.1    
      factory                     99      5.715         0.000              0.0     0.714      2.0    
      targets_and_sources         99      0.001         0.000              0.0     0.000      0.0    
    sources                        0      0.001         0.000              0.0     0.000      0.0    
    targets                        0      0.001         0.000              0.0     0.000      0.0    
  update                           0      0.000         0.000             74.0     0.000      0.0    
    update_conns                   0      0.000         0.001            367.1     0.000      0.0    
      local                        0      0.000         0.000              0.0     0.000      0.0    
      sort                         0      0.000         0.000              0.0     0.000      0.0    
      remote                       0      0.000         0.000             43.6     0.000      0.0    
        connections                0      0.000         0.000              0.0     0.000      0.0    
        destructure                0      0.000         0.000              0.0     0.000      0.0    
        sort                       0      0.000         0.000              0.0     0.000      0.0    
      collect_gids                 0      0.000         0.000              0.0     0.000      0.0    
      destructure                  0      0.000         0.000              0.0     0.000      0.0    
      index                        0      0.000         0.000              0.0     0.000      0.0    
      raw                          0      0.000         0.000              0.0     0.000      0.0    
      generated                    0      0.000         0.000              0.0     0.000      0.0    
      partition                    0      0.000         0.000              0.0     0.000      0.0    
    generators                     0      0.000         0.000              0.0     0.000      0.0

thorstenhater · 2025-12-09T11:53:59Z

Hi @marvinKaster,

you are running into a CI issue that has been fixed in main. Please rebase and it should be gone.

…hical_timer # Conflicts: # arbor/communication/communicator.cpp # arbor/simulation.cpp

thorstenhater · 2026-01-07T10:26:38Z

Hi @marvinKaster,

#2490 has a fix for the last failing test. Could you give it a review?

Best,
TH

thorstenhater

Hi @marvinKaster,

thanks, that will make life a bit easier. I've left a few suggestions.

thorstenhater · 2026-01-12T12:11:54Z

@@ -12,12 +12,16 @@
        }

    // leave a profling region


Possibly a note for later updates. We could also offer a RAII macro here now, in the style of:

struct AutoProf { AutoProf(const auto& label): lbl(label) { enter(lbl); } ~AutoProf() { leave(lbl); } std::string lbl; };

Even some macro magick could be used to generate unique names based on __FILE__ and __LINE__.

See other comment

Possibly the allocation of strings is problematic. Anyhow, not needed. I played around with tracy, which is extremely nice to work with, but I recon not really playing well with MPI.

thorstenhater · 2026-01-12T12:22:56Z

-    #define PL arb::profile::profiler_leave
+    #define PL(name) \
+        { \
+            static std::size_t region_id_ = arb::profile::profiler_region_id(#name); \


Another possible extension: we could record FILE LINE FUNCTION when we set up the region.

I gave it and AutoProf a try today, and somehow made everything slow. Maybe that is an extension for another PR

Yes, that was not a request to add it here.

thorstenhater · 2026-01-27T17:28:11Z

 void recorder::leave(region_id_type index, const std::vector<std::string>& names) {
    if(current_timer_stack[current_timer_stack.size()-1] != index) {
-        throw std::runtime_error("recorder::leave without matching recorder::enter Trying to leave "+names[index] + " but currently in "+names[current_timer_stack[current_timer_stack.size()-1]]);
+        throw std::runtime_error("recorder::leave without matching recorder::enter Trying to leave "+names[index] + " but currently in "+names[current_timer_stack[current_timer_stack.size()-1]] + + " TimerStack: " + timer_stack_to_string(current_timer_stack, names));


+ + looks off to me?

Thanks for catching that. Interesting that it compiled with it

It compiles and work like you wanted it to
https://godbolt.org/z/n8jhnoj7h

Reason is that C/C++ have unary plus and minus:

int x = 42; -x; // negate +x; // same as x -x + +x; // 0

see https://godbolt.org/z/6Thd4PWMv
That it works for strings might tell us something about C++ and operator overloading ;)

Hmm. I would guess then the string literal is interpreted as char*, which has an unary +.

Specifically that, yes.

thorstenhater · 2026-01-28T19:53:49Z

Now CI is running into an error on UTF-8 decode?

marvinKaster · 2026-01-29T08:12:50Z

@thorstenhater I have no idea how removing the '+' in leave() causes an UTF-8 error in the python call to profiler_summary / print_profiler_summary. I will investigate

thorstenhater · 2026-01-29T08:45:50Z

Possibly an interaction with MPI?

marvinKaster · 2026-02-04T09:40:38Z

I tried reproducing the error locally, but it works every time for me. A rerun of the job was also successful. It seems to be hard to reproduce.

I don't think MPI is involved. As far as I understand, the methods don't call MPI at any point.

thorstenhater · 2026-02-04T09:42:18Z

The suspicion was that the output gets passed through github's interface and two interleaved MPI ranks produced something weird.

@thorstenhater

# Preliminary release notes for v0.12 ## What's Changed * V0.11.0 rc by @thorstenhater in #2454 * Release finalisation by @thorstenhater in #2455 * CSCS CI by @thorstenhater in #2448 * Re-factor connection setup and event dispatch. by @thorstenhater in #2449 * Add tiled busyring by @thorstenhater in #2456 * Fill in a missing part of the docs by @thorstenhater in #2462 * Major Optimisations in Label Resolution by @thorstenhater in #2458 * Refactor domain decomposition by @thorstenhater in #2457 * Add an escape hatch to label resolution by @thorstenhater in #2459 * Fix crash on probding elided values by @thorstenhater in #2466 * Only store PRNG data if needed by @thorstenhater in #2467 * 🐍 Polish `label_dict` by @thorstenhater in #2451 * use better builtins for double max/min by @thorstenhater in #2469 * Remove typed map and refactor cable cell by @thorstenhater in #2468 * Many small refactoring / clean-ups / memory savings by @thorstenhater in #2465 * Bump pb11 to latest major version by @thorstenhater in #2475 * Fix GPU test issues by @ibanezbm in #2479 * Align versions by @thorstenhater in #2481 * Add probing of eX. by @thorstenhater in #2478 * Add trivial compiler test by @thorstenhater in #2488 * Replace MPI_Allgatherv with MPI_Alltoallv for communication pattern by @ibanezbm in #2460 * Use CBRNG in schedules. by @thorstenhater in #2386 * Update year 🎉 by @thorstenhater in #2491 * Don't use deprecated numpy functions by @thorstenhater in #2490 * Co-simulation tutorial by @thorstenhater in #2492 * Nested timers by @marvinKaster in #2486 * Clean-up iclamp interface by @thorstenhater in #2494 * Fix override by @thorstenhater in #2493 * Better use of __restrict__ by @thorstenhater in #2476 * Add AdEx cells. by @thorstenhater in #2230 * units in cv policy by @thorstenhater in #2495 * Flat map in mechanism description for 1.5x speed-up in synapse creation by @thorstenhater in #2501 * Perf/compress contiguous by @thorstenhater in #2470 * Allow more SWC files in the parser by @thorstenhater in #2471 * STDP case for busyring benchmark by @jlubo in #2489 * round robin load balance by @thorstenhater in #2500 ## New Contributors * @ibanezbm made their first contribution in #2479 * @marvinKaster made their first contribution in #2486 **Full Changelog**: v0.11.0...v0.12.0

@thorstenhater

# Release notes This release constitutes a major improvement in terms of parallel performance by replacing the underlying MPI algorithm (see our paper at IPDPS'26) and setup time by improving label resolution and adding the access to raw labels. On the functional side, we introduced AdEx cells, added a new load balancing method, and probes for the reversal potential. ## What's Changed * V0.11.0 rc by @thorstenhater in #2454 * Release finalisation by @thorstenhater in #2455 * CSCS CI by @thorstenhater in #2448 * Re-factor connection setup and event dispatch. by @thorstenhater in #2449 * Add tiled busyring by @thorstenhater in #2456 * Fill in a missing part of the docs by @thorstenhater in #2462 * Major Optimisations in Label Resolution by @thorstenhater in #2458 * Refactor domain decomposition by @thorstenhater in #2457 * Add an escape hatch to label resolution by @thorstenhater in #2459 * Fix crash on probding elided values by @thorstenhater in #2466 * Only store PRNG data if needed by @thorstenhater in #2467 * 🐍 Polish `label_dict` by @thorstenhater in #2451 * use better builtins for double max/min by @thorstenhater in #2469 * Remove typed map and refactor cable cell by @thorstenhater in #2468 * Many small refactoring / clean-ups / memory savings by @thorstenhater in #2465 * Bump pb11 to latest major version by @thorstenhater in #2475 * Fix GPU test issues by @ibanezbm in #2479 * Align versions by @thorstenhater in #2481 * Add probing of eX. by @thorstenhater in #2478 * Add trivial compiler test by @thorstenhater in #2488 * Replace MPI_Allgatherv with MPI_Alltoallv for communication pattern by @ibanezbm in #2460 * Use CBRNG in schedules. by @thorstenhater in #2386 * Update year 🎉 by @thorstenhater in #2491 * Don't use deprecated numpy functions by @thorstenhater in #2490 * Co-simulation tutorial by @thorstenhater in #2492 * Nested timers by @marvinKaster in #2486 * Clean-up iclamp interface by @thorstenhater in #2494 * Fix override by @thorstenhater in #2493 * Better use of __restrict__ by @thorstenhater in #2476 * Add AdEx cells. by @thorstenhater in #2230 * units in cv policy by @thorstenhater in #2495 * Flat map in mechanism description for 1.5x speed-up in synapse creation by @thorstenhater in #2501 * Perf/compress contiguous by @thorstenhater in #2470 * Allow more SWC files in the parser by @thorstenhater in #2471 * STDP case for busyring benchmark by @jlubo in #2489 * round robin load balance by @thorstenhater in #2500 ## New Contributors * @ibanezbm made their first contribution in #2479 * @marvinKaster made their first contribution in #2486 **Full Changelog**: v0.11.0...v0.12.0

marvinKaster and others added 9 commits August 15, 2025 18:00

Hierarchical timers

2397ef6

fix threaded calculation and remove empty timers

a4cad57

Reformatting

e34013e

Merge branch 'arbor-sim:master' into hierarchical_timer

40a8790

Merge branch 'arbor-sim:master' into hierarchical_timer

8a6cb0e

Fix no profiling build

0edce23

More timers

4ef2f9c

Fixed test

e8cadb6

Fixed more tests

9ba714c

marvinKaster added 9 commits December 23, 2025 12:54

Hierarchical timers

78f4efb

fix threaded calculation and remove empty timers

9869c9a

Reformatting

447aebd

Fix no profiling build

46c1c55

More timers

cc50f44

Fixed test

3ac05fc

Fixed more tests

0918846

Merge remote-tracking branch 'origin/hierarchical_timer' into hierarc…

e83e267

…hical_timer # Conflicts: # arbor/communication/communicator.cpp # arbor/simulation.cpp

Fixed merge

8b44e33

Merge branch 'arbor-sim:master' into hierarchical_timer

a491a16

thorstenhater reviewed Jan 12, 2026

View reviewed changes

Incorporation TH's comments

a42c4a4

thorstenhater requested changes Jan 27, 2026

View reviewed changes

Fix + +

e4c94af

thorstenhater approved these changes Feb 4, 2026

View reviewed changes

thorstenhater merged commit b890b87 into arbor-sim:master Feb 4, 2026
40 of 42 checks passed

thorstenhater mentioned this pull request Mar 3, 2026

Suspected issue in Profiler #2497

Closed

thorstenhater mentioned this pull request Apr 15, 2026

final clean-up before v0.12 #2504

Merged

thorstenhater mentioned this pull request Apr 16, 2026

Release v0.12 #2506

Merged

Conversation

marvinKaster commented Nov 27, 2025

Uh oh!

thorstenhater commented Dec 9, 2025

Uh oh!

thorstenhater commented Jan 7, 2026

Uh oh!

thorstenhater left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

thorstenhater commented Jan 28, 2026

Uh oh!

marvinKaster commented Jan 29, 2026

Uh oh!

thorstenhater commented Jan 29, 2026

Uh oh!

marvinKaster commented Feb 4, 2026

Uh oh!

thorstenhater commented Feb 4, 2026

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants