Optimize new tracing system

[jutaro]

Use profiling to find out ways to optimize the new tracing for minimal CPU, Memory and GC load.

[deepfire]

@jutaro, you can use the following targets for perf comparisons:

• make chainsync-early-byron-auto
• make chainsync-early-byron-oldtracing-auto

This will provide the results in:

• run/$RUN/node-*/
• run/$RUN/analysis/

[jutaro]

The number of messages put into the tracing system is very high. In this test in one node more then 2 million messages are send. This results in some processing and allocation overhead, even when all messages are filtered out. Here are profiling entries that are shown in an chainsync-early-byron run:

COST CENTRE                                      MODULE                                                                      SRC                                                                                                                                                                             %time %alloc  ticks     bytes

compute                                          Control.Tracer.Arrow                                                        src/Control/Tracer/Arrow.hs:60:1-29                                                                                                                                               1.5    3.5   5903 8726029392
traceMaybe                                       Control.Tracer                                                              src/Control/Tracer.hs:(218,1)-(220,44)                                                                                                                                            1.3    2.5   5021 6213680240
mkCardanoTracer'                                 Cardano.Logging.Tracer.Composed                                             src/Cardano/Logging/Tracer/Composed.hs:(79,1)-(130,53)                                                                                                                            1.3    3.1   4910 7687232000
withNamespaceConfig                              Cardano.Logging.Configuration                                               src/Cardano/Logging/Configuration.hs:(68,1)-(165,111)                                                                                                                             0.6    1.1   2506 2601343704
runTracerA                                       Control.Tracer.Arrow                                                        src/Control/Tracer/Arrow.hs:(40,1)-(41,63)                                                                                                                                        0.4    0.6   1746 1413708696
filterSeverityFromConfig                         Cardano.Logging.Configuration                                               src/Cardano/Logging/Configuration.hs:(172,1)-(187,25)                                                                                                                             0.4    1.1   1376 2702387088
foldMTraceM                                      Cardano.Logging.Trace                                                       src/Cardano/Logging/Trace.hs:(250,1)-(263,43)                                                                                                                                     0.3    0.7   1184 1753121856
squelchUnless                                    Control.Tracer                                                              src/Control/Tracer.hs:224:1-68                                                                                                                                                    0.3    0.2   1041 480139720
withNamesAppended                                Cardano.Logging.Trace                                                       src/Cardano/Logging/Trace.hs:(129,1)-(134,8)    

We see that at least 6,3% of processing goes into tracing and > 13% of allocation. In reality these numbers will be higher.

[jutaro]

We added a new maybeSilent combinator, which switch off any message of a particular tracer based on the configuration. If the configuration gives a value of Silence for the namespace of the tracer, no messages will be send.

maybeSilent :: forall m a. (MonadIO m) =>
     Namespace
  -> Trace m a
  -> m (Trace m a)

The maybeSilent combinator is put by default as the first filter in the tracer build by mkCardanoTracer.
With this optimization the picture changes drastically when the tracers are set to silence, and processing time for traces goes down from 6,3% to 2,4% and allocation from 13% to 3.2%:

mkCardanoTracer'                                 Cardano.Logging.Tracer.Composed                                             src/Cardano/Logging/Tracer/Composed.hs:(80,1)-(132,53)                                                                                                                            0.6    1.0  16412 5614346608
runTracerA                                       Control.Tracer.Arrow                                                        src/Control/Tracer/Arrow.hs:(40,1)-(41,63)                                                                                                                                        0.5    0.6  12667 3195551848
compute                                          Control.Tracer.Arrow                                                        src/Control/Tracer/Arrow.hs:60:1-29                                                                                                                                               0.4    0.8  10932 4565994712
filterTrace                                      Cardano.Logging.Trace                                                       src/Cardano/Logging/Trace.hs:(60,1)-(67,34)                                                                                                                                       0.3    0.4   6966 2017980992
withNamespaceConfig                              Cardano.Logging.Configuration                                               src/Cardano/Logging/Configuration.hs:(106,1)-(203,111)                                                                                                                            0.2    0.3   6264 1918168888
mkDispatchTracers                                Cardano.Node.Tracing.Tracers                                                src/Cardano/Node/Tracing/Tracers.hs:(89,1)-(231,5)                                                                                                                                0.2    0.0   5735  12100416
emit                                             Control.Tracer.Arrow                                                        src/Control/Tracer/Arrow.hs:51:1-57                                                                                                                                               0.2    0.1   5676 490470464
                                                                                                                                                                                                                                                                                                               2.4    3.2     

The drawback of this, is that metrics is suppressed, if it is send by a tracer that has been silenced. In the generated documentation you can find by which tracer a metrics gets send.

[jutaro]

With an optimized solution in which metrics are not filtered by maybeSilent we get:

mkCardanoTracer'                                 Cardano.Logging.Tracer.Composed                                             src/Cardano/Logging/Tracer/Composed.hs:(80,1)-(132,53)                                                                                                                            1.3    2.0   8247 7538723384
runTracerA                                       Control.Tracer.Arrow                                                        src/Control/Tracer/Arrow.hs:(40,1)-(41,63)                                                                                                                                        1.0    1.0   6201 3751086760
compute                                          Control.Tracer.Arrow                                                        src/Control/Tracer/Arrow.hs:60:1-29                                                                                                                                               0.7    1.5   4693 5610969640
withNamespaceConfig                              Cardano.Logging.Configuration                                               src/Cardano/Logging/Configuration.hs:(106,1)-(203,111)                                                                                                                            0.5    0.6   3429 2389268944
filterSeverityFromConfig                         Cardano.Logging.Configuration                                               src/Cardano/Logging/Configuration.hs:(210,1)-(234,31)                                                                                                                             0.3    0.7   1931 2658906248
foldMTraceM                                      Cardano.Logging.Trace                                                       src/Cardano/Logging/Trace.hs:(265,1)-(278,43)                                                                                                                                     0.2    0.4   1437 1651559368
emit                                             Control.Tracer.Arrow                                                        src/Control/Tracer/Arrow.hs:51:1-57                                                                                                                                               0.2    0.0   1425   1077504
filterTrace                                      Cardano.Logging.Trace                                                       src/Cardano/Logging/Trace.hs:(60,1)-(67,34)                                                                                                                                       0.2    0.2   1289 607997448

This means computation is reduced from 6,3% to 3,6(2,4)% and allocation from 13% to 5.2(3,2)%. The numbers in parenthesis are from the solution above, which as well filters out metrics for silent tracers.
In a run in which about 40000 messages are written to standard-out and forwarded, and all metrics are written, about 6% of processor time is used for tracing, and 8% of allocation.

[Jimbo4350]

Closing this. If this is still relevant please reopen.