Optimize new tracing - Githubissues

IntersectMBO / cardano-node

The core component that is used to participate in a Cardano decentralised blockchain.

https://cardano.org

Apache License 2.0

3.06k stars 720 forks source link

Optimize new tracing #5272

Closed jutaro closed 1 year ago

jutaro commented 1 year ago

Performance enhancements for tracing, metrics, datapoints and forwarding.

Old tracing should soon be complemented and then superseded by new tracing. New tracing has a lot of enhancements:

All tracers are always on and respect the configured severity
All tracers can be configured individually based on hierarchical namespaces. This is possible down to individual messages.
Traces are forwarded to a cardano-tracer process, which can handle the traces of many nodes
When old tracing will be gone, tracing can be reconfigured in a running node
A complete documentation of all trace messages, metrics and datapoints can be automatically generated. Please see the generated tracing configuration reference at: trace-messages

All these enhancement should not burden cardano-node with additional performance penalties. This issue has been opened to measure the performance and profiling the running node in different scenarios, and then find optimizations for new tracing.

jutaro commented 1 year ago

The importance of these optimizations gets clear when we look to the numbers:

It depends on the test case how many trace messages and metrics are send every second, but it can be easily 40 to 100 messages, which are send every second in a node
With a standard configuration about 15 of these messages may actually be shown every second
XX metrics are updated every second

So the tracing system has to be carefully tuned to not burden the node runtime resources more then necessary. When we output all messages, the runtime overhead for tracing will be unavoidable high, where Aeson, which is used for the Json serialization of the log messages constitutes the biggest burden.

jutaro commented 1 year ago

The test setup is based on:

The workbench commit fb27207e07cfa0fd53a9d3faeae0c4e932ed70a6
The workbench local cluster run trace-bench
The branch jutaro/benchmark-new is used for testing. measuring and optimizing
All runs are done 3 times: start-cluster -n 3 and the variance analysis of the workbench is used.

Run with different options:

new tracing
old tracing
with profiling
without profiling
with standard tracer config
with all tracers on config
with ghc 8.10.7
with ghc 9.2.6

Uses a standard config of new tracers, which resembles the configuration of old tracing and gives the worbench analysis tool all information it needs for its work:

  UseTraceDispatcher   = true;
    TraceOptions  = {
      "" =
        { severity = "Notice";
          backends = [
            "Stdout MachineFormat"
            "EKGBackend"
            ] ++ optional tracer
                 "Forwarder";
        };

      ## These are comparision-specific config deviations from the default.
      ##
      ## "Resources".backends = ["EKGBackend"];

      "Net.AcceptPolicy".severity = "Info";
      "BlockFetch.Client".severity = "Info";
      "BlockFetch.Server".severity = "Info";
      "ChainDB".severity = "Info";
      "ChainSync.Client".severity = "Info";
      "ChainSync.ServerBlock".severity = "Info";
      "ChainSync.ServerHeader".severity = "Info";
      "Forge.Loop".severity = "Info";
      "Net.ConnectionManager".severity = "Info";
      "Net.Startup.DiffusionInit".severity = "Info";
      "Net.DNSResolver".severity = "Info";
      "Net.ErrorPolicy".severity = "Info";
      "Net.InboundGovernor".severity = "Info";
      "Net.Subscription.DNS".severity = "Info";
      "Net.Subscription.IP".severity = "Info";
      "Net.Peers".severity = "Info";
      "Net.PeerSelection".severity = "Info";
      "Net.Server".severity = "Info";
      "Mempool".severity = "Info";
      "Resources".severity= "Info";
      "TxSubmission.TxInbound".severity = "Info";

      "ChainDB.FollowerEvent.NewFollower".severity = "Debug";
      "ChainDB.FollowerEvent.FollowerNoLongerInMem".severity = "Debug";
      "ChainDB.AddBlockEvent.AddedBlockToQueue".severity = "Debug";
      "ChainDB.IteratorEvent.StreamFromVolatileDB".severity = "Debug";
      "ChainDB.GCEvent.PerformedGC".severity = "Debug";
      "ChainDB.GCEvent.ScheduledGC".severity = "Debug";
      "ChainDB.ImmDbEvent.CacheEvent.CurrentChunkHit".severity = "Debug";
      "ChainDB.ImmDbEvent.CacheEvent.PastChunkHit".severity = "Debug";
      "Forge.Loop.BlockContext".severity = "Debug";
      "Forge.Loop.LedgerState".severity = "Debug";
      "Forge.Loop.LedgerView".severity = "Debug";
      "Forge.Loop.ForgingMempoolSnapshot".severity = "Debug";
      "Forge.Loop.ForgeTickedLedgerState".severity = "Debug";
      "TxSubmission.TxInbound.CanRequestMoreTxs".severity = "Debug";
      "TxSubmission.TxInbound.CannotRequestMoreTxs".severity = "Debug";
      "TxSubmission.TxInbound.Collected".severity = "Debug";
      "TxSubmission.TxInbound.Processed".severity = "Debug";

      "TraceBenchTxSubServAck".severity = "Debug";
      "TraceBenchTxSubSummary".severity = "Debug";
      "TraceTxSubmissionCollected".severity = "Debug";
      "TraceTxSubmissionProcessed".severity = "Debug";
    };
  };

jutaro commented 1 year ago

New tracing (optimized) results (ghc 8.10.7)

Started with: make cls trace-bench-prof profiling=time

#+TITLE: 2023-07-03-12-57-02803_variance_8.1.1
#+SUBTITLE: filters: unfiltered, slot range: raw(0-334, I 334 total) filtered(0-334, I 334 total), filtered 1.0
#+DATE: 2023-07-03 14:09:10 UTC
#+VERSION: locli 1.29 (508137)
|---+---------------------------------+--------------|
| ! |                       Parameter |        Value |
|---+---------------------------------+--------------|
| # |                   Analysis date |   2023-07-03 |
| # |       Cluster system start date |   2023-07-03 |
| # |       Cluster system start time |     12:45:39 |
| # |                      Identifier |        8.1.1 |
| # |                       Run batch |        plain |
| # |            cardano-node version |        8.1.1 |
| # |     ouroboros-consensus version |      0.7.0.0 |
| # |       ouroboros-network version |      0.8.1.1 |
| # |     cardano-ledger-core version |      1.2.0.0 |
| # |             plutus-core version |      1.5.0.1 |
| # |          cardano-crypto version |        1.1.2 |
| # |         cardano-prelude version |      0.1.0.2 |
| # |                cardano-node git |      02803bc |
| # |         ouroboros-consensus git |      143e9df |
| # |           ouroboros-network git |      0012bba |
| # |         cardano-ledger-core git |      6db84a7 |
| # |                 plutus-core git |      e42d1a0 |
| # |              cardano-crypto git |      6568a5e |
| # |             cardano-prelude git |      ef87bb9 |
| # |                             Era |      babbage |
| # |             Delegation map size |            0 |
| # |          Starting UTxO set size |            0 |
| # |                Extra tx payload |          100 |
| # |                       Tx inputs |            2 |
| # |                      Tx Outputs |            2 |
| # |                             TPS |         15.0 |
| # |               Transaction count |         9000 |
| # |                   Plutus script |          --- |
| # |                        Machines |            6 |
| # |       Number of filters applied |            1 |
| # | Log text lines emitted per host | 6213.6111111 |
| # |    Log objects emitted per host | 6178.6111111 |
| # |   Log objects analysed per host | 3431.0555555 |
| # |                Host run time, s |      527.322 |
| # |          Host log line rate, Hz |       15.862 |
| # |      Total log objects analysed |        17819 |
| # |                     Run time, s |          366 |
| # |        Analysed run duration, s |          334 |
| # |             Run time efficiency |         0.91 |
| # |            Node start spread, s |          .03 |
| # |             Node stop spread, s |       32.002 |
| # |   Perf analysis start spread, s |            0 |
| # |    Perf analysis stop spread, s |           32 |
| # |                  Slots analysed |          495 |
| # |                 Blocks analysed |           15 |
| # |                 Blocks rejected |            0 |

#+TITLE: 2023-07-03-12-44-02803-trace-bench-bage-sup-prof, 2023-07-03-12-51-02803-trace-bench-bage-sup-prof, 2023-07-03-12-57-02803-trace-bench-bage-sup-prof
#+SUBTITLE: filters: unfiltered, slot range: raw(0-334, I 334 total) filtered(0-334, I 334 total), filtered 1.0
#+DATE: 2023-07-03 14:09:10 UTC
#+VERSION: locli 1.29 (508137)
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| ! |                   metric | average |    CoV |    min |    max | stddev |  range | precision |   size |
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| # |     Forge loop starts, # |  .95230 | .08674 | .85691 |   1.0  | .08261 | .14308 |      .0   |   3.0  |
| # |     Process CPU usage, % |  1.4625 | .07066 | 1.3931 | 1.5813 | .10335 | .18820 |      .0   |   3.0  |
| # |      RTS GC CPU usage, % |  .11483 | .11513 | .10406 | .12959 | .01322 | .02552 |      .0   |   3.0  |
| # | RTS Mutator CPU usage, % |  1.4315 | .06181 | 1.3792 | 1.5337 | .08848 | .15452 |      .0   |   3.0  |
| # |             Major GCs, # |  .01286 | .15643 | .01110 | .01506 | .00201 | .00395 |      .0   |   3.0  |
| # |             Minor GCs, # |  .24032 | .06898 | .22521 | .25806 | .01657 | .03284 |      .0   |   3.0  |
| # |           Kernel RSS, MB |  150.98 | .00488 | 150.50 | 151.83 | .73689 | 1.3327 |      .0   |   3.0  |
| # |        RTS heap size, MB |  6.3171 | .02716 | 6.1497 | 6.4926 | .17159 | .34288 |      .0   |   3.0  |
| # |  RTS live GC dateset, MB |  54.935 | .01208 | 54.427 | 55.686 | .66416 | 1.2594 |      .0   |   3.0  |
| # |     RTS alloc rate, MB/s |  7.6641 | .07152 | 7.1676 | 8.2524 | .54816 | 1.0847 |      .0   |   3.0  |
| # |      Network reads, KB/s |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
| # |     Network writes, KB/s |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
| # |   Filesystem reads, KB/s |  .01425 | 1.6039 |   .0   | .04062 | .02286 | .04062 |      .0   |   3.0  |
| # |  Filesystem writes, KB/s |  .71117 | .06880 | .65591 | .74901 | .04893 | .09309 |      .0   |   3.0  |
| # |     CPU 85% spans, slots |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| _ |                 nSamples |         |        |        |        |        |        |           |        |
| # |                     8928 |         |        |        |        |        |        |           |        |

#+TITLE: 2023-07-03-12-57-02803_variance_8.1.1
#+SUBTITLE: filters: unfiltered, slot range: raw(0-334, I 334 total) filtered(0-334, I 334 total), filtered 1.0
#+DATE: 2023-07-03 14:09:10 UTC
#+VERSION: locli 1.29 (508137)
|---+---------------------------------------+---------+-------+----------+--------------------------------------------------------------|
| ! |                             Parameter | time, % | range | alloc, % |                                              source location |
|---+---------------------------------------+---------+-------+----------+--------------------------------------------------------------|
| # |                              unquoted |     4.5 |   1.5 |      8.6 |                  src/Data/Aeson/Encoding/Builder.hs:114:1-47 |
| # |                      psbUseAsSizedPtr |     2.2 |   1.8 |      0.0 |      src/Cardano/Crypto/PinnedSizedBytes.hs:(276,1)-(278,17) |
| # |                       timeToTimeOfDay |     1.9 |   1.4 |      1.6 | lib/Data/Time/LocalTime/Internal/TimeOfDay.hs:(84,1)-(90,18) |
| # |                                  text |     1.8 |   1.6 |      3.8 |                  src/Data/Aeson/Encoding/Builder.hs:110:1-49 |
| # |                                  fn_3 |     1.5 |   0.9 |      2.1 |                             src/Data/SOP/Classes.hs:147:1-55 |
| # |           withNamespaceConfig.mkTrace |     1.5 |   0.7 |      1.0 |        src/Cardano/Logging/Configuration.hs:(157,5)-(253,98) |
| # |                                     . |     1.5 |   1.8 |      1.3 |                   src/Control/Tracer/Arrow.hs:(64,3)-(72,68) |
| # |                                  MAIN |     1.4 |   1.2 |      0.1 |                                                    |
| # |                           readTBQueue |     1.4 |   0.7 |      0.4 |           Control/Concurrent/STM/TBQueue.hs:(120,1)-(137,18) |
| # |                 unsafeUseAsCStringLen |     1.3 |   0.7 |      0.0 |                           Data/ByteString/Unsafe.hs:287:1-91 |
| # |                            formatTime |     1.3 |   1.2 |      1.8 |        lib/Data/Time/Format/Format/Class.hs:(306,1)-(310,55) |
| # | throwSocketErrorIfMinus1RetryMayBlock |     1.2 |   0.5 |      0.1 |                  Network/Socket/Internal.hs:(208,1)-(209,53) |
| # |                     socketAsMuxBearer |     1.2 |   0.6 |      0.3 |             src/Network/Mux/Bearer/Socket.hs:(52,1)-(148,28) |
| # |               withTimeoutSerialNative |     1.2 |   0.1 |      0.9 |                           src/Network/Mux/Timeout.hs:67:1-54 |
| # |                              fromList |     1.2 |   0.0 |      0.2 |                     Data/HashMap/Internal/Strict.hs:638:1-70 |
| # |                                string |     1.2 |   0.0 |      0.9 |          src/Data/Aeson/Encoding/Builder.hs:(122,1)-(123,66) |
| # |        machineFormatter'.\.machineObj |     1.1 |   0.5 |      0.5 |           src/Cardano/Logging/Formatter.hs:(156,17)-(162,60) |
| # |                               hPutStr |     1.1 |   0.0 |      0.3 |                         src/Data/Text/IO.hs:(182,1)-(193,56) |
| # |                                    fn |     1.1 |   0.0 |      0.6 |                             src/Data/SOP/Classes.hs:145:1-23 |
| # |                     runPeerWithSink.\ |     1.1 |   0.7 |      1.2 | src/Trace/Forward/Run/TraceObject/Forwarder.hs:(45,5)-(50,62 |
| # |                                   *** |     1.1 |   1.0 |      2.0 |                   src/Control/Tracer/Arrow.hs:(76,3)-(79,76) |
| # |                                 liftF |     1.1 |   0.3 |      0.9 |                     src/Control/Monad/Free/Class.hs:153:1-26 |
| # |                          useAsCString |     1.1 |   0.3 |      0.5 |                        Data/ByteString.hs:(1582,1)-(1587,25) |
| # |                          stdoutThread |     1.1 |   0.0 |      0.1 |        src/Cardano/Logging/Tracer/Standard.hs:(79,1)-(82,17) |
| # |                                 trans |     1.1 |   0.9 |      1.1 |            src/Control/State/Transition/Extended.hs:416:1-36 |
| # |                         formatGeneral |     1.1 |   0.1 |      0.9 |                lib/Data/Time/Format/Format/Class.hs:56:1-123 |
| # |                       judgmentContext |     1.1 |   0.3 |      0.5 |            src/Control/State/Transition/Extended.hs:432:1-36 |
| # |                               liftSTS |     1.1 |   0.0 |      0.7 |            src/Control/State/Transition/Extended.hs:428:1-30 |
| # |                              runQuery |     1.1 |   0.0 |      0.6 | src/ouroboros-consensus/Ouroboros/Consensus/HardFork/History |
| # |                       lensMemoRawType |     1.0 |   0.1 |      0.6 |             src/Cardano/Ledger/MemoBytes.hs:(234,1)-(235,83) |
| # |                    decodeWithByteSpan |     1.0 |   1.3 |      1.5 |                src/Codec/CBOR/Decoding.hs:(1005,1)-(1009,29) |
| # |                               compute |     1.0 |   0.2 |      1.0 |                          src/Control/Tracer/Arrow.hs:60:1-29 |
| # |                                object |     1.0 |   0.9 |      1.0 |           src/Data/Aeson/Encoding/Builder.hs:(97,1)-(102,61) |
| # |                               hcliftA |     0.9 |   1.5 |      1.9 |                             src/Data/SOP/Classes.hs:317:1-50 |
| # |                             toBuilder |     0.9 |   3.2 |      1.1 |                     src/Codec/CBOR/Write.hs:(102,1)-(103,57) |
| # |                                  exp' |     0.9 |   0.7 |      1.1 |           src/Cardano/Ledger/NonIntegral.hs:(178,1)-(183,34) |
| # |                             sampleAll |     0.8 |   0.0 |      1.2 |                           System/Metrics.hs:(599,1)-(606,35) |
| # |                                hliftA |     0.7 |   0.9 |      1.1 |                             src/Data/SOP/Classes.hs:261:1-44 |
| # |                          foldrWithKey |     0.6 |   0.8 |      1.2 |                            src/Data/Aeson/KeyMap.hs:232:1-48 |
| # |                      readProcNetInOut |     0.6 |   1.6 |      1.8 |        src/Cardano/Logging/Resources/Linux.hs:(87,1)-(95,31) |
| # |                                 sList |     0.6 |   0.9 |      1.7 |                                 src/Data/SOP/Sing.hs:85:1-51 |
| # |                       codecEKGForward |     0.5 |   1.7 |      1.2 |          src/System/Metrics/Protocol/Codec.hs:(32,1)-(80,88) |
| # |                      toLazyByteString |     0.5 |   0.5 |      3.8 |                  Data/ByteString/Builder.hs:(281,1)-(282,62) |
| # |                              cpure_NP |     0.5 |   0.8 |      1.0 |                          src/Data/SOP/NP.hs:(256,1)-(258,29) |
| # |                              forHuman |     0.4 |   0.3 |      1.2 | src/Cardano/Node/Tracing/Tracers/Consensus.hs:(126,3)-(127,6 |
| # |                       showHostAddress |     0.4 |   0.0 |      1.2 |                     Network/Socket/Info.hsc:(434,1)-(436,72) |
| # |               updateStakeDistribution |     0.4 |   0.0 |      1.0 | src/Cardano/Ledger/Shelley/LedgerState/IncrementalStake.hs:( |
| # |                            encodeUtf8 |     0.3 |   0.6 |      1.2 |                   src/Data/Text/Encoding.hs:(433,1)-(448,37) |
| # |                             serialize |     0.1 |   0.1 |      1.3 |         src/Cardano/Ledger/Binary/Encoding.hs:(48,1)-(54,37) |

jutaro commented 1 year ago

Old-tracing results (ghc 8.10.7)

Started with: make cls trace-bench-oldtracing-prof WB_PROFILING=time

#+TITLE: 2023-07-05-14-24-02803_variance_8.1.1
#+SUBTITLE: filters: unfiltered, slot range: raw(0-351, I 351 total) filtered(0-351, I 351 total), filtered 1.0
#+DATE: 2023-07-05 15:36:33 UTC
#+VERSION: locli 1.29 (508137)
|---+---------------------------------+--------------|
| ! |                       Parameter |        Value |
|---+---------------------------------+--------------|
| # |                   Analysis date |   2023-07-05 |
| # |       Cluster system start date |   2023-07-05 |
| # |       Cluster system start time |     14:11:45 |
| # |                      Identifier |        8.1.1 |
| # |                       Run batch |        plain |
| # |            cardano-node version |        8.1.1 |
| # |     ouroboros-consensus version |      0.7.0.0 |
| # |       ouroboros-network version |      0.8.1.1 |
| # |     cardano-ledger-core version |      1.2.0.0 |
| # |             plutus-core version |      1.5.0.1 |
| # |          cardano-crypto version |        1.1.2 |
| # |         cardano-prelude version |      0.1.0.2 |
| # |                cardano-node git |      02803bc |
| # |         ouroboros-consensus git |      143e9df |
| # |           ouroboros-network git |      0012bba |
| # |         cardano-ledger-core git |      6db84a7 |
| # |                 plutus-core git |      e42d1a0 |
| # |              cardano-crypto git |      6568a5e |
| # |             cardano-prelude git |      ef87bb9 |
| # |                             Era |      babbage |
| # |             Delegation map size |            0 |
| # |          Starting UTxO set size |            0 |
| # |                Extra tx payload |          100 |
| # |                       Tx inputs |            2 |
| # |                      Tx Outputs |            2 |
| # |                             TPS |         15.0 |
| # |               Transaction count |         9000 |
| # |                   Plutus script |          --- |
| # |                        Machines |            6 |
| # |       Number of filters applied |            1 |
| # | Log text lines emitted per host | 6356.2222222 |
| # |    Log objects emitted per host | 6322.2222222 |
| # |   Log objects analysed per host | 3390.8333333 |
| # |                Host run time, s |      554.043 |
| # |          Host log line rate, Hz |       14.397 |
| # |      Total log objects analysed |        19786 |
| # |                     Run time, s |          412 |
| # |        Analysed run duration, s |          380 |
| # |             Run time efficiency |         0.92 |
| # |            Node start spread, s |          .29 |
| # |             Node stop spread, s |           75 |
| # |   Perf analysis start spread, s |            0 |
| # |    Perf analysis stop spread, s |           75 |
| # |                  Slots analysed |          521 |
| # |                 Blocks analysed |           14 |
| # |                 Blocks rejected |            1 |

#+TITLE: 2023-07-05-14-11-02803-trace-bench-oldtracing-bage-sup-prof, 2023-07-05-14-18-02803-trace-bench-oldtracing-bage-sup-prof, 2023-07-05-14-24-02803-trace-bench-oldtracing-bage-sup-prof
#+SUBTITLE: filters: unfiltered, slot range: raw(0-351, I 351 total) filtered(0-351, I 351 total), filtered 1.0
#+DATE: 2023-07-05 15:36:33 UTC
#+VERSION: locli 1.29 (508137)
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| ! |                   metric | average |    CoV |    min |    max | stddev |  range | precision |   size |
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| # |     Forge loop starts, # |  .95230 | .08675 | .85690 |   1.0  | .08261 | .14309 |      .0   |   3.0  |
| # |     Process CPU usage, % |  1.2112 | .02991 | 1.1822 | 1.2518 | .03623 | .06956 |      .0   |   3.0  |
| # |      RTS GC CPU usage, % |  .01698 | .06530 | .01572 | .01781 | .00110 | .00208 |      .0   |   3.0  |
| # | RTS Mutator CPU usage, % |  1.1979 | .02831 | 1.1708 | 1.2359 | .03392 | .06517 |      .0   |   3.0  |
| # |             Major GCs, # |  .00936 | .10379 | .00872 | .01048 | .00097 | .00176 |      .0   |   3.0  |
| # |             Minor GCs, # |  .19128 | .05217 | .18012 | .19935 | .00998 | .01923 |      .0   |   3.0  |
| # |           Kernel RSS, MB |  162.04 | .00550 | 161.19 | 162.97 | .89240 | 1.7786 |      .0   |   3.0  |
| # |        RTS heap size, MB |  4.5046 | .02410 | 4.4321 | 4.6294 | .10856 | .19734 |      .0   |   3.0  |
| # |  RTS live GC dateset, MB |  46.507 | .00599 | 46.303 | 46.824 | .27873 | .52097 |      .0   |   3.0  |
| # |     RTS alloc rate, MB/s |  6.0315 | .05537 | 5.6682 | 6.3252 | .33401 | .65705 |      .0   |   3.0  |
| # |      Network reads, KB/s |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
| # |     Network writes, KB/s |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
| # |   Filesystem reads, KB/s |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
| # |  Filesystem writes, KB/s |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
| # |     CPU 85% spans, slots |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| _ |                 nSamples |         |        |        |        |        |        |           |        |
| # |                     9412 |         |        |        |        |        |        |           |        |

#+TITLE: 2023-07-05-14-24-02803_variance_8.1.1
#+SUBTITLE: filters: unfiltered, slot range: raw(0-351, I 351 total) filtered(0-351, I 351 total), filtered 1.0
#+DATE: 2023-07-05 15:36:33 UTC
#+VERSION: locli 1.29 (508137)
|---+---------------------------------------+---------+-------+----------+--------------------------------------------------------------|
| ! |                             Parameter | time, % | range | alloc, % |                                              source location |
|---+---------------------------------------+---------+-------+----------+--------------------------------------------------------------|
| # |                              unquoted |     3.6 |   1.3 |      6.2 |                  src/Data/Aeson/Encoding/Builder.hs:114:1-47 |
| # |                                 async |     2.9 |   1.2 |      1.9 |                         Control/Concurrent/Async.hs:264:1-35 |
| # |                           bEffectuate |     2.5 |   1.3 |      2.8 |                      src/Cardano/BM/Data/Backend.lhs:80:7-17 |
| # |                            appendName |     2.4 |   4.6 |      3.5 |                      src/Cardano/BM/Trace.lhs:(65,1)-(68,28) |
| # |                      psbUseAsSizedPtr |     2.0 |   1.6 |      0.0 |      src/Cardano/Crypto/PinnedSizedBytes.hs:(276,1)-(278,17) |
| # |                                concat |     1.7 |   1.1 |      4.1 |                          src/Data/Text.hs:(1002,1)-(1014,36) |
| # | throwSocketErrorIfMinus1RetryMayBlock |     1.7 |   1.9 |      0.1 |                  Network/Socket/Internal.hs:(208,1)-(209,53) |
| # |                                  fn_3 |     1.7 |   1.0 |      2.3 |                             src/Data/SOP/Classes.hs:147:1-55 |
| # |                                object |     1.6 |   1.3 |      3.3 |           src/Data/Aeson/Encoding/Builder.hs:(97,1)-(102,61) |
| # |                       timeToTimeOfDay |     1.6 |   1.2 |      1.4 | lib/Data/Time/LocalTime/Internal/TimeOfDay.hs:(84,1)-(90,18) |
| # |                     readResourceStats |     1.5 |   3.6 |      2.6 |             src/Cardano/BM/Counters/Linux.lhs:(46,1)-(72,62) |
| # |                            formatTime |     1.5 |   1.3 |      2.2 |        lib/Data/Time/Format/Format/Class.hs:(306,1)-(310,55) |
| # |                                  MAIN |     1.5 |   1.4 |      0.1 |                                                    |
| # |                               hcliftA |     1.4 |   1.1 |      2.1 |                             src/Data/SOP/Classes.hs:317:1-50 |
| # |                              itemJson |     1.4 |   1.0 |      0.7 |                                   src/Katip/Core.hs:566:1-64 |
| # |                              fromList |     1.3 |   0.8 |      0.4 |           src/Data/Map/Strict/Internal.hs:(1501,1)-(1534,97) |
| # |                                  text |     1.3 |   1.3 |      3.7 |                  src/Data/Aeson/Encoding/Builder.hs:110:1-49 |
| # |                                    fn |     1.2 |   0.6 |      0.8 |                             src/Data/SOP/Classes.hs:145:1-23 |
| # |                          processQueue |     1.2 |   0.5 |      1.1 |       src/Cardano/BM/Backend/ProcessQueue.lhs:(31,1)-(40,47) |
| # |                         toOrdinalDate |     1.2 |   0.3 |      0.8 |         lib/Data/Time/Calendar/OrdinalDate.hs:(10,1)-(20,57) |
| # |                                  year |     1.1 |   0.1 |      0.5 | attoparsec-iso8601/src/Data/Attoparsec/Time.hs:(93,1)-(98,26 |
| # |                 unsafeUseAsCStringLen |     1.1 |   0.0 |      0.0 |                           Data/ByteString/Unsafe.hs:287:1-91 |
| # |                               utcTime |     1.1 |   0.3 |      0.6 |                 src/Data/Aeson/Encoding/Internal.hs:431:1-42 |
| # |                             hPutStrLn |     1.1 |   0.0 |      0.3 |                            src/Data/Text/Lazy/IO.hs:142:1-46 |
| # |                      knownSlotWatcher |     1.1 |   0.3 |      0.2 | src/ouroboros-consensus/Ouroboros/Consensus/BlockchainTime/A |
| # |                          useAsCString |     1.1 |   0.3 |      0.5 |                        Data/ByteString.hs:(1582,1)-(1587,25) |
| # |                               hPutStr |     1.1 |   0.0 |      0.4 |                         src/Data/Text/IO.hs:(182,1)-(193,56) |
| # |                       judgmentContext |     1.1 |   0.0 |      0.7 |            src/Control/State/Transition/Extended.hs:432:1-36 |
| # |                               liftSTS |     1.1 |   0.0 |      0.7 |            src/Control/State/Transition/Extended.hs:428:1-30 |
| # |               withTimeoutSerialNative |     1.1 |   0.1 |      1.0 |                           src/Network/Mux/Timeout.hs:67:1-54 |
| # |                                 liftF |     1.0 |   0.5 |      1.1 |                     src/Control/Monad/Free/Class.hs:153:1-26 |
| # |                                  exp' |     1.0 |   1.3 |      1.3 |           src/Cardano/Ledger/NonIntegral.hs:(178,1)-(183,34) |
| # |                              mkLOMeta |     1.0 |   0.7 |      1.4 |             src/Cardano/BM/Data/LogItem.lhs:(125,1)-(135,48) |
| # |               showPaddedFixedFraction |     1.0 |   0.1 |      0.6 |          lib/Data/Time/Format/Format/Class.hs:(76,1)-(83,46) |
| # |                mainTraceConditionally |     1.0 |   0.1 |      0.2 |      src/Cardano/BM/Backend/Switchboard.lhs:(125,1)-(133,26) |
| # |                     socketAsMuxBearer |     1.0 |   0.1 |      0.3 |             src/Network/Mux/Bearer/Socket.hs:(52,1)-(148,28) |
| # |                    decodeWithByteSpan |     1.0 |   1.5 |      1.7 |                src/Codec/CBOR/Decoding.hs:(1005,1)-(1009,29) |
| # |                       lensMemoRawType |     0.9 |   0.3 |      1.0 |             src/Cardano/Ledger/MemoBytes.hs:(234,1)-(235,83) |
| # |                                 trans |     0.9 |   1.2 |      1.2 |            src/Control/State/Transition/Extended.hs:416:1-36 |
| # |                           getBackends |     0.9 |   0.7 |      1.5 |      src/Cardano/BM/Configuration/Model.lhs:(168,1)-(180,42) |
| # |                         formatGeneral |     0.8 |   0.6 |      1.1 |                lib/Data/Time/Format/Format/Class.hs:56:1-123 |
| # |                                hliftA |     0.8 |   0.6 |      1.3 |                             src/Data/SOP/Classes.hs:261:1-44 |
| # |                          testSubTrace |     0.8 |   1.4 |      1.3 |      src/Cardano/BM/Configuration/Model.lhs:(712,1)-(728,30) |
| # |                                 sList |     0.7 |   0.8 |      2.0 |                                 src/Data/SOP/Sing.hs:85:1-51 |
| # |                      toLazyByteString |     0.6 |   0.5 |      4.1 |                  Data/ByteString/Builder.hs:(281,1)-(282,62) |
| # |                              cpure_NP |     0.5 |   0.8 |      1.2 |                          src/Data/SOP/NP.hs:(256,1)-(258,29) |
| # |                           stripPrefix |     0.4 |   0.6 |      1.2 |                          src/Data/Text.hs:(1806,1)-(1808,32) |
| # |                      getProducedValue |     0.4 |   0.0 |      1.1 |          src/Cardano/Ledger/Shelley/UTxO.hs:(156,1)-(159,91) |
| # |            validateOutputTooSmallUTxO |     0.3 |   0.2 |      1.0 |    src/Cardano/Ledger/Babbage/Rules/Utxo.hs:(268,1)-(283,13) |
| # |               updateStakeDistribution |     0.3 |   0.1 |      1.2 | src/Cardano/Ledger/Shelley/LedgerState/IncrementalStake.hs:( |
| # |              valueEitherBabbageTxOutL |     0.2 |   0.0 |      1.1 |          src/Cardano/Ledger/Babbage/TxOut.hs:(234,1)-(242,5) |
| # |                             serialize |     0.1 |   0.1 |      1.8 |         src/Cardano/Ledger/Binary/Encoding.hs:(48,1)-(54,37) |

jutaro commented 1 year ago

New tracing (optimized) results (ghc 9.2.7)

Started with: make cls trace-bench-prof profiling=time

#+TITLE: 2023-07-06-14-37-55fda_variance_8.1.1
#+SUBTITLE: filters: unfiltered, slot range: raw(0-297, I 297 total) filtered(0-297, I 297 total), filtered 1.0
#+DATE: 2023-07-06 14:45:36 UTC
#+VERSION: locli 1.29 (55fda1)
|---+---------------------------------+--------------|
| ! |                       Parameter |        Value |
|---+---------------------------------+--------------|
| # |                   Analysis date |   2023-07-06 |
| # |       Cluster system start date |   2023-07-06 |
| # |       Cluster system start time |     14:27:03 |
| # |                      Identifier |        8.1.1 |
| # |                       Run batch |        plain |
| # |            cardano-node version |        8.1.1 |
| # |     ouroboros-consensus version |      0.7.0.0 |
| # |       ouroboros-network version |      0.8.1.1 |
| # |     cardano-ledger-core version |      1.2.0.0 |
| # |             plutus-core version |      1.5.0.1 |
| # |          cardano-crypto version |        1.1.2 |
| # |         cardano-prelude version |      0.1.0.2 |
| # |                cardano-node git |      55fda13 |
| # |         ouroboros-consensus git |      143e9df |
| # |           ouroboros-network git |      0012bba |
| # |         cardano-ledger-core git |      6db84a7 |
| # |                 plutus-core git |      e42d1a0 |
| # |              cardano-crypto git |      6568a5e |
| # |             cardano-prelude git |      ef87bb9 |
| # |                             Era |      babbage |
| # |             Delegation map size |            0 |
| # |          Starting UTxO set size |            0 |
| # |                Extra tx payload |          100 |
| # |                       Tx inputs |            2 |
| # |                      Tx Outputs |            2 |
| # |                             TPS |         15.0 |
| # |               Transaction count |         9000 |
| # |                   Plutus script |          --- |
| # |                        Machines |            6 |
| # |       Number of filters applied |            1 |
| # | Log text lines emitted per host | 5391.1111111 |
| # |    Log objects emitted per host | 5356.1111111 |
| # |   Log objects analysed per host | 3094.8888888 |
| # |                Host run time, s |      337.988 |
| # |          Host log line rate, Hz |       15.984 |
| # |      Total log objects analysed |        18560 |
| # |                     Run time, s |          361 |
| # |        Analysed run duration, s |          328 |
| # |             Run time efficiency |         0.90 |
| # |            Node start spread, s |        .0227 |
| # |             Node stop spread, s |       5.0035 |
| # |   Perf analysis start spread, s |            0 |
| # |    Perf analysis stop spread, s |            5 |
| # |                  Slots analysed |          305 |
| # |                 Blocks analysed |           15 |
| # |                 Blocks rejected |            0 |

**#+TITLE: 2023-07-06-14-26-55fda-trace-bench-bage-sup-prof, 2023-07-06-14-32-55fda-trace-bench-bage-sup-prof, 2023-07-06-14-37-55fda-trace-bench-bage-sup-prof
#+SUBTITLE: filters: unfiltered, slot range: raw(0-297, I 297 total) filtered(0-297, I 297 total), filtered 1.0
#+DATE: 2023-07-06 14:45:36 UTC
#+VERSION: locli 1.29 (55fda1)
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| ! |                   metric | average |    CoV |    min |    max | stddev |  range | precision |   size |
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| # |     Forge loop starts, # |    1.0  |   .0   |   1.0  |   1.0  |   .0   |   .0   |      .0   |   3.0  |
| # |     Process CPU usage, % |  1.5910 | .01182 | 1.5788 | 1.6126 | .01880 | .03380 |      .0   |   3.0  |
| # |      RTS GC CPU usage, % |  .08221 | .13628 | .06976 | .09148 | .01120 | .02172 |      .0   |   3.0  |
| # | RTS Mutator CPU usage, % |  1.5682 | .01650 | 1.5454 | 1.5963 | .02588 | .05093 |      .0   |   3.0  |
| # |             Major GCs, # |  .01651 | .12652 | .01418 | .01822 | .00208 | .00404 |      .0   |   3.0  |
| # |             Minor GCs, # |  .38662 | .01743 | .37967 | .39314 | .00674 | .01346 |      .0   |   3.0  |
| # |           Kernel RSS, MB |  149.61 | .00756 | 148.42 | 150.67 | 1.1322 | 2.2546 |      .0   |   3.0  |
| # |        RTS heap size, MB |  8.0064 | .03109 | 7.7249 | 8.1977 | .24895 | .47275 |      .0   |   3.0  |
| # |  RTS live GC dateset, MB |  58.285 | .02006 | 56.973 | 59.219 | 1.1695 | 2.2461 |      .0   |   3.0  |
| # |     RTS alloc rate, MB/s |  11.847 | .01497 | 11.742 | 12.052 | .17743 | .30989 |      .0   |   3.0  |
| # |      Network reads, KB/s |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
| # |     Network writes, KB/s |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
| # |   Filesystem reads, KB/s |  .00222 | .92903 |   .0   | .00407 | .00206 | .00407 |      .0   |   3.0  |
| # |  Filesystem writes, KB/s |  .72733 | .04884 | .69900 | .76719 | .03552 | .06819 |      .0   |   3.0  |
| # |     CPU 85% spans, slots |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| _ |                 nSamples |         |        |        |        |        |        |           |        |
| # |                     5520 |         |        |        |        |        |        |           |        |
**

#+TITLE: 2023-07-06-14-37-55fda_variance_8.1.1
#+SUBTITLE: filters: unfiltered, slot range: raw(0-297, I 297 total) filtered(0-297, I 297 total), filtered 1.0
#+DATE: 2023-07-06 14:45:36 UTC
#+VERSION: locli 1.29 (55fda1)
|---+---------------------------------------+---------+-------+----------+--------------------------------------------------------------|
| ! |                             Parameter | time, % | range | alloc, % |                                              source location |
|---+---------------------------------------+---------+-------+----------+--------------------------------------------------------------|
| # |                              unquoted |     4.2 |   1.7 |      5.5 |                  src/Data/Aeson/Encoding/Builder.hs:114:1-47 |
| # |                                  fn_3 |     3.0 |   1.3 |      9.2 |                             src/Data/SOP/Classes.hs:147:1-55 |
| # |                                  text |     2.1 |   1.2 |      2.6 |                  src/Data/Aeson/Encoding/Builder.hs:110:1-49 |
| # |                      psbUseAsSizedPtr |     2.0 |   1.6 |      0.0 |      src/Cardano/Crypto/PinnedSizedBytes.hs:(276,1)-(278,17) |
| # |                       timeToTimeOfDay |     1.8 |   1.0 |      1.1 | lib/Data/Time/LocalTime/Internal/TimeOfDay.hs:(94,1)-(102,18 |
| # |                            formatTime |     1.4 |   1.0 |      1.4 |        lib/Data/Time/Format/Format/Class.hs:(331,1)-(336,57) |
| # |                                 trans |     1.4 |   0.7 |      0.9 |            src/Control/State/Transition/Extended.hs:416:1-36 |
| # |                             toBuilder |     1.4 |   1.1 |      0.9 |                     src/Codec/CBOR/Write.hs:(102,1)-(103,57) |
| # |                     runPeerWithSink.\ |     1.3 |   0.8 |      0.8 | src/Trace/Forward/Run/TraceObject/Forwarder.hs:(45,5)-(50,62 |
| # |                           readTBQueue |     1.3 |   0.8 |      0.3 |           Control/Concurrent/STM/TBQueue.hs:(121,1)-(141,18) |
| # |           withNamespaceConfig.mkTrace |     1.3 |   0.5 |      0.6 |        src/Cardano/Logging/Configuration.hs:(157,5)-(253,98) |
| # |                                     . |     1.3 |   0.5 |      0.8 |                   src/Control/Tracer/Arrow.hs:(64,3)-(72,68) |
| # |                    decodeWithByteSpan |     1.3 |   0.6 |      2.0 |                src/Codec/CBOR/Decoding.hs:(1005,1)-(1009,29) |
| # |                         formatGeneral |     1.3 |   0.6 |      0.9 |          lib/Data/Time/Format/Format/Class.hs:(73,1)-(74,84) |
| # | throwSocketErrorIfMinus1RetryMayBlock |     1.2 |   0.6 |      0.1 |                  Network/Socket/Internal.hs:(208,1)-(209,53) |
| # |                          stdoutThread |     1.2 |   0.3 |      0.0 |        src/Cardano/Logging/Tracer/Standard.hs:(79,1)-(82,17) |
| # |               withTimeoutSerialNative |     1.2 |   0.6 |      0.4 |                           src/Network/Mux/Timeout.hs:67:1-54 |
| # |                                  MAIN |     1.2 |   0.7 |      0.1 |                                                    |
| # |                                hliftA |     1.2 |   0.0 |      0.8 |                             src/Data/SOP/Classes.hs:261:1-44 |
| # |        machineFormatter'.\.machineObj |     1.1 |   0.3 |      0.6 |           src/Cardano/Logging/Formatter.hs:(156,17)-(162,60) |
| # |                       codecEKGForward |     1.1 |   0.3 |      0.6 |          src/System/Metrics/Protocol/Codec.hs:(32,1)-(80,88) |
| # |                                 liftF |     1.1 |   0.3 |      0.6 |                     src/Control/Monad/Free/Class.hs:153:1-26 |
| # |                 unsafeUseAsCStringLen |     1.1 |   0.0 |      0.0 |                           Data/ByteString/Unsafe.hs:285:1-88 |
| # |                               hcliftA |     1.1 |   1.1 |      1.1 |                             src/Data/SOP/Classes.hs:317:1-50 |
| # |                               compute |     1.0 |   0.1 |      0.7 |                          src/Control/Tracer/Arrow.hs:60:1-29 |
| # |                                   *** |     1.0 |   0.9 |      1.3 |                   src/Control/Tracer/Arrow.hs:(76,3)-(79,76) |
| # |                       judgmentContext |     1.0 |   0.0 |      0.3 |            src/Control/State/Transition/Extended.hs:432:1-36 |
| # |                       lensMemoRawType |     1.0 |   0.0 |      0.7 |             src/Cardano/Ledger/MemoBytes.hs:(234,1)-(235,83) |
| # |                                object |     1.0 |   0.0 |      0.7 |           src/Data/Aeson/Encoding/Builder.hs:(97,1)-(102,61) |
| # |                       showHostAddress |     1.0 |   0.0 |      0.7 |                     Network/Socket/Info.hsc:(434,1)-(436,72) |
| # |                          useAsCString |     1.0 |   0.0 |      0.2 |                        Data/ByteString.hs:(1779,1)-(1783,24) |
| # |                               liftSTS |     0.7 |   0.6 |      1.0 |            src/Control/State/Transition/Extended.hs:428:1-30 |
| # |            validateOutputTooSmallUTxO |     0.7 |   0.3 |      2.2 |    src/Cardano/Ledger/Babbage/Rules/Utxo.hs:(268,1)-(283,13) |
| # |               updateStakeDistribution |     0.6 |   0.0 |      2.3 | src/Cardano/Ledger/Shelley/LedgerState/IncrementalStake.hs:( |
| # |                      toLazyByteString |     0.6 |   0.8 |      2.4 |                  Data/ByteString/Builder.hs:(278,1)-(279,62) |
| # |                getAlonzoScriptsNeeded |     0.5 |   0.8 |      2.7 |           src/Cardano/Ledger/Alonzo/UTxO.hs:(129,1)-(151,99) |
| # |                                 sList |     0.5 |   0.7 |      1.2 |                                 src/Data/SOP/Sing.hs:85:1-51 |
| # |                      babbageTxScripts |     0.5 |   0.5 |      2.8 |            src/Cardano/Ledger/Babbage/Tx.hs:(142,1)-(146,73) |
| # |                            encodeUtf8 |     0.5 |   1.0 |      1.1 |                   src/Data/Text/Encoding.hs:(462,1)-(477,37) |
| # |                              produced |     0.5 |   0.3 |      2.1 |          src/Cardano/Ledger/Shelley/UTxO.hs:(146,1)-(147,75) |
| # |              validateOutputTooBigUTxO |     0.5 |   0.1 |      2.1 |     src/Cardano/Ledger/Alonzo/Rules/Utxo.hs:(395,1)-(406,20) |
| # |                      readProcNetInOut |     0.4 |   0.3 |      1.0 |        src/Cardano/Logging/Resources/Linux.hs:(87,1)-(95,31) |
| # |                        witsVKeyNeeded |     0.4 |   0.3 |      2.0 |    src/Cardano/Ledger/Alonzo/Rules/Utxow.hs:(433,1)-(487,19) |
| # |     validateOutputBootAddrAttrsTooBig |     0.3 |   0.1 |      1.9 |    src/Cardano/Ledger/Shelley/Rules/Utxo.hs:(566,1)-(576,24) |
| # |                  getConsumedMaryValue |     0.3 |   0.3 |      1.4 |               src/Cardano/Ledger/Mary/UTxO.hs:(57,1)-(64,69) |
| # |             validateScriptsWellFormed |     0.3 |   0.4 |      1.4 |   src/Cardano/Ledger/Babbage/Rules/Utxow.hs:(235,1)-(252,83) |
| # |         allSizedOutputsBabbageTxBodyF |     0.2 |   0.4 |      1.4 |        src/Cardano/Ledger/Babbage/TxBody.hs:(363,1)-(368,48) |
| # |                      getProducedValue |     0.2 |   0.7 |      1.4 |          src/Cardano/Ledger/Shelley/UTxO.hs:(156,1)-(159,91) |
| # |                       updateUTxOState |     0.2 |   0.4 |      1.4 |     src/Cardano/Ledger/Shelley/Rules/Utxo.hs:(600,1)-(614,9) |

jutaro commented 1 year ago

Old tracing results (ghc 9.2.7)

Started with: make cls trace-bench-oldtracing-prof WB_PROFILING=time

#+TITLE: 2023-07-06-12-38-55fda_variance_8.1.1
#+SUBTITLE: filters: unfiltered, slot range: raw(0-361, I 361 total) filtered(0-361, I 361 total), filtered 1.0
#+DATE: 2023-07-06 13:49:49 UTC
#+VERSION: locli 1.29 (55fda1)
|---+---------------------------------+--------------|
| ! |                       Parameter |        Value |
|---+---------------------------------+--------------|
| # |                   Analysis date |   2023-07-06 |
| # |       Cluster system start date |   2023-07-06 |
| # |       Cluster system start time |     12:20:19 |
| # |                      Identifier |        8.1.1 |
| # |                       Run batch |        plain |
| # |            cardano-node version |        8.1.1 |
| # |     ouroboros-consensus version |      0.7.0.0 |
| # |       ouroboros-network version |      0.8.1.1 |
| # |     cardano-ledger-core version |      1.2.0.0 |
| # |             plutus-core version |      1.5.0.1 |
| # |          cardano-crypto version |        1.1.2 |
| # |         cardano-prelude version |      0.1.0.2 |
| # |                cardano-node git |      55fda13 |
| # |         ouroboros-consensus git |      143e9df |
| # |           ouroboros-network git |      0012bba |
| # |         cardano-ledger-core git |      6db84a7 |
| # |                 plutus-core git |      e42d1a0 |
| # |              cardano-crypto git |      6568a5e |
| # |             cardano-prelude git |      ef87bb9 |
| # |                             Era |      babbage |
| # |             Delegation map size |            0 |
| # |          Starting UTxO set size |            0 |
| # |                Extra tx payload |          100 |
| # |                       Tx inputs |            2 |
| # |                      Tx Outputs |            2 |
| # |                             TPS |         15.0 |
| # |               Transaction count |         9000 |
| # |                   Plutus script |          --- |
| # |                        Machines |            6 |
| # |       Number of filters applied |            1 |
| # | Log text lines emitted per host |       7754.0 |
| # |    Log objects emitted per host |       7720.0 |
| # |   Log objects analysed per host | 4212.2222222 |
| # |                Host run time, s |      649.115 |
| # |          Host log line rate, Hz |       14.431 |
| # |      Total log objects analysed |        27626 |
| # |                     Run time, s |          670 |
| # |        Analysed run duration, s |          637 |
| # |             Run time efficiency |         0.95 |
| # |            Node start spread, s |           .3 |
| # |             Node stop spread, s |          165 |
| # |   Perf analysis start spread, s |            0 |
| # |    Perf analysis stop spread, s |          165 |
| # |                  Slots analysed |          616 |
| # |                 Blocks analysed |           15 |
| # |                 Blocks rejected |            0 |

#+TITLE: 2023-07-06-12-19-55fda-trace-bench-oldtracing-bage-sup-prof, 2023-07-06-12-26-55fda-trace-bench-oldtracing-bage-sup-prof, 2023-07-06-12-38-55fda-trace-bench-oldtracing-bage-sup-prof
#+SUBTITLE: filters: unfiltered, slot range: raw(0-361, I 361 total) filtered(0-361, I 361 total), filtered 1.0
#+DATE: 2023-07-06 13:49:49 UTC
#+VERSION: locli 1.29 (55fda1)
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| ! |                   metric | average |    CoV |    min |    max | stddev |  range | precision |   size |
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| # |     Forge loop starts, # |  .95230 | .08675 | .85690 |   1.0  | .08261 | .14309 |      .0   |   3.0  |
| # |     Process CPU usage, % |  1.1668 | .07429 | 1.0937 | 1.2626 | .08669 | .16885 |      .0   |   3.0  |
| # |      RTS GC CPU usage, % |  .00721 | .09317 | .00647 | .00778 | .00067 | .00131 |      .0   |   3.0  |
| # | RTS Mutator CPU usage, % |  1.1590 | .07562 | 1.0850 | 1.2558 | .08765 | .17080 |      .0   |   3.0  |
| # |             Major GCs, # |  .00852 | .19376 | .00686 | .01017 | .00165 | .00330 |      .0   |   3.0  |
| # |             Minor GCs, # |  .32369 | .07865 | .29944 | .35021 | .02546 | .05076 |      .0   |   3.0  |
| # |           Kernel RSS, MB |  137.56 | .00168 | 137.33 | 137.79 | .23121 | .46236 |      .0   |   3.0  |
| # |        RTS heap size, MB |  5.3174 | .03806 | 5.1458 | 5.5406 | .20239 | .39480 |      .0   |   3.0  |
| # |  RTS live GC dateset, MB |  48.259 | .00824 | 47.826 | 48.608 | .39777 | .78239 |      .0   |   3.0  |
| # |     RTS alloc rate, MB/s |  9.7306 | .07034 | 9.0410 | 10.409 | .68445 | 1.3687 |      .0   |   3.0  |
| # |      Network reads, KB/s |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
| # |     Network writes, KB/s |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
| # |   Filesystem reads, KB/s |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
| # |  Filesystem writes, KB/s |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
| # |     CPU 85% spans, slots |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| _ |                 nSamples |         |        |        |        |        |        |           |        |
| # |                     111> |         |        |        |        |        |        |           |        |

#+TITLE: 2023-07-06-12-38-55fda_variance_8.1.1
#+SUBTITLE: filters: unfiltered, slot range: raw(0-361, I 361 total) filtered(0-361, I 361 total), filtered 1.0
#+DATE: 2023-07-06 13:49:49 UTC
#+VERSION: locli 1.29 (55fda1)
|---+---------------------------------------+---------+-------+----------+--------------------------------------------------------------|
| ! |                             Parameter | time, % | range | alloc, % |                                              source location |
|---+---------------------------------------+---------+-------+----------+--------------------------------------------------------------|
| # |                              unquoted |     3.3 |   1.6 |      3.9 |                  src/Data/Aeson/Encoding/Builder.hs:114:1-47 |
| # |                                  fn_3 |     3.0 |   1.5 |      10. |                             src/Data/SOP/Classes.hs:147:1-55 |
| # |                                 async |     2.5 |   1.0 |      1.1 |                         Control/Concurrent/Async.hs:264:1-35 |
| # |                           bEffectuate |     2.2 |   1.2 |      1.6 |                      src/Cardano/BM/Data/Backend.lhs:80:7-17 |
| # |                      psbUseAsSizedPtr |     2.1 |   2.0 |      0.0 |      src/Cardano/Crypto/PinnedSizedBytes.hs:(276,1)-(278,17) |
| # |                            appendName |     1.9 |   2.8 |      2.1 |                      src/Cardano/BM/Trace.lhs:(65,1)-(68,28) |
| # |                                object |     1.8 |   1.0 |      2.3 |           src/Data/Aeson/Encoding/Builder.hs:(97,1)-(102,61) |
| # |                                 trans |     1.6 |   1.0 |      1.0 |            src/Control/State/Transition/Extended.hs:416:1-36 |
| # |                                  text |     1.6 |   0.9 |      2.5 |                  src/Data/Aeson/Encoding/Builder.hs:110:1-49 |
| # |                            formatTime |     1.6 |   0.9 |      1.5 |        lib/Data/Time/Format/Format/Class.hs:(331,1)-(336,57) |
| # |                                concat |     1.5 |   1.2 |      2.5 |                            src/Data/Text.hs:(977,1)-(989,36) |
| # |                       timeToTimeOfDay |     1.5 |   1.2 |      0.9 | lib/Data/Time/LocalTime/Internal/TimeOfDay.hs:(94,1)-(102,18 |
| # |                     readResourceStats |     1.4 |   2.9 |      1.7 |             src/Cardano/BM/Counters/Linux.lhs:(46,1)-(72,62) |
| # |                                  MAIN |     1.4 |   1.6 |      0.0 |                                                    |
| # |                         formatGeneral |     1.3 |   0.7 |      1.1 |          lib/Data/Time/Format/Format/Class.hs:(73,1)-(74,84) |
| # |                    decodeWithByteSpan |     1.3 |   0.8 |      1.6 |                src/Codec/CBOR/Decoding.hs:(1005,1)-(1009,29) |
| # |                               hcliftA |     1.3 |   0.8 |      1.2 |                             src/Data/SOP/Classes.hs:317:1-50 |
| # |                              itemJson |     1.3 |   0.7 |      0.4 |                                   src/Katip/Core.hs:566:1-64 |
| # |                              fromList |     1.2 |   0.6 |      0.2 |           src/Data/Map/Strict/Internal.hs:(1501,1)-(1534,97) |
| # |                               utcTime |     1.2 |   0.5 |      0.4 |                 src/Data/Aeson/Encoding/Internal.hs:431:1-42 |
| # |                              mkLOMeta |     1.2 |   0.8 |      0.9 |             src/Cardano/BM/Data/LogItem.lhs:(125,1)-(135,48) |
| # | throwSocketErrorIfMinus1RetryMayBlock |     1.2 |   0.3 |      0.1 |                  Network/Socket/Internal.hs:(208,1)-(209,53) |
| # |               withTimeoutSerialNative |     1.2 |   0.3 |      0.6 |                           src/Network/Mux/Timeout.hs:67:1-54 |
| # |                                 liftF |     1.1 |   0.3 |      0.6 |                     src/Control/Monad/Free/Class.hs:153:1-26 |
| # |                                   run |     1.1 |   0.0 |      0.4 |                              src/Data/Text/Array.hs:143:1-34 |
| # |                          useAsCString |     1.1 |   0.3 |      0.3 |                        Data/ByteString.hs:(1779,1)-(1783,24) |
| # |                         toOrdinalDate |     1.1 |   0.3 |      0.5 |         lib/Data/Time/Calendar/OrdinalDate.hs:(12,1)-(23,57) |
| # |                                    fn |     1.1 |   0.0 |      0.5 |                             src/Data/SOP/Classes.hs:145:1-23 |
| # |                                hliftA |     1.0 |   0.1 |      0.9 |                             src/Data/SOP/Classes.hs:261:1-44 |
| # |                          testSubTrace |     1.0 |   0.5 |      1.2 |      src/Cardano/BM/Configuration/Model.lhs:(712,1)-(728,30) |
| # |                             hPutStrLn |     1.0 |   0.1 |      0.2 |                            src/Data/Text/Lazy/IO.hs:140:1-46 |
| # |                       lensMemoRawType |     1.0 |   0.0 |      0.7 |             src/Cardano/Ledger/MemoBytes.hs:(234,1)-(235,83) |
| # |                          processQueue |     1.0 |   0.0 |      0.8 |       src/Cardano/BM/Backend/ProcessQueue.lhs:(31,1)-(40,47) |
| # |                               liftSTS |     0.9 |   1.0 |      1.1 |            src/Control/State/Transition/Extended.hs:428:1-30 |
| # |                           getBackends |     0.9 |   0.6 |      1.0 |      src/Cardano/BM/Configuration/Model.lhs:(168,1)-(180,42) |
| # |            validateOutputTooSmallUTxO |     0.7 |   0.5 |      2.1 |    src/Cardano/Ledger/Babbage/Rules/Utxo.hs:(268,1)-(283,13) |
| # |                                 sList |     0.6 |   0.7 |      1.2 |                                 src/Data/SOP/Sing.hs:85:1-51 |
| # |                              produced |     0.6 |   0.6 |      2.0 |          src/Cardano/Ledger/Shelley/UTxO.hs:(146,1)-(147,75) |
| # |                      toLazyByteString |     0.6 |   0.8 |      2.4 |                  Data/ByteString/Builder.hs:(278,1)-(279,62) |
| # |               updateStakeDistribution |     0.6 |   0.3 |      2.1 | src/Cardano/Ledger/Shelley/LedgerState/IncrementalStake.hs:( |
| # |                getAlonzoScriptsNeeded |     0.6 |   0.4 |      3.1 |           src/Cardano/Ledger/Alonzo/UTxO.hs:(129,1)-(151,99) |
| # |                      babbageTxScripts |     0.6 |   0.5 |      3.1 |            src/Cardano/Ledger/Babbage/Tx.hs:(142,1)-(146,73) |
| # |                        witsVKeyNeeded |     0.4 |   0.4 |      2.3 |    src/Cardano/Ledger/Alonzo/Rules/Utxow.hs:(433,1)-(487,19) |
| # |              validateOutputTooBigUTxO |     0.4 |   0.3 |      2.1 |     src/Cardano/Ledger/Alonzo/Rules/Utxo.hs:(395,1)-(406,20) |
| # |     validateOutputBootAddrAttrsTooBig |     0.4 |   0.0 |      1.8 |    src/Cardano/Ledger/Shelley/Rules/Utxo.hs:(566,1)-(576,24) |
| # |             validateScriptsWellFormed |     0.3 |   0.5 |      1.5 |   src/Cardano/Ledger/Babbage/Rules/Utxow.hs:(235,1)-(252,83) |
| # |                       updateUTxOState |     0.3 |   0.3 |      1.5 |     src/Cardano/Ledger/Shelley/Rules/Utxo.hs:(600,1)-(614,9) |
| # |                  getConsumedMaryValue |     0.3 |   0.3 |      1.5 |               src/Cardano/Ledger/Mary/UTxO.hs:(57,1)-(64,69) |
| # |                      getProducedValue |     0.3 |   0.5 |      1.5 |          src/Cardano/Ledger/Shelley/UTxO.hs:(156,1)-(159,91) |
| # |         allSizedOutputsBabbageTxBodyF |     0.3 |   0.3 |      1.5 |        src/Cardano/Ledger/Babbage/TxBody.hs:(363,1)-(368,48) |

jutaro commented 1 year ago

New tracing (optimized) results - all trace messages written (ghc 9.2.7)

Started with: make cls trace-bench-prof profiling=time

#+TITLE: 2023-07-07-10-55-55fda_variance_8.1.1
#+SUBTITLE: filters: unfiltered, slot range: raw(0-362, I 362 total) filtered(0-362, I 362 total), filtered 1.0
#+DATE: 2023-07-07 11:01:11 UTC
#+VERSION: locli 1.29 (55fda1)
|---+---------------------------------+--------------|
| ! |                       Parameter |        Value |
|---+---------------------------------+--------------|
| # |                   Analysis date |   2023-07-07 |
| # |       Cluster system start date |   2023-07-07 |
| # |       Cluster system start time |     09:37:54 |
| # |                      Identifier |        8.1.1 |
| # |                       Run batch |        plain |
| # |            cardano-node version |        8.1.1 |
| # |     ouroboros-consensus version |      0.7.0.0 |
| # |       ouroboros-network version |      0.8.1.1 |
| # |     cardano-ledger-core version |      1.2.0.0 |
| # |             plutus-core version |      1.5.0.1 |
| # |          cardano-crypto version |        1.1.2 |
| # |         cardano-prelude version |      0.1.0.2 |
| # |                cardano-node git |      55fda13 |
| # |         ouroboros-consensus git |      143e9df |
| # |           ouroboros-network git |      0012bba |
| # |         cardano-ledger-core git |      6db84a7 |
| # |                 plutus-core git |      e42d1a0 |
| # |              cardano-crypto git |      6568a5e |
| # |             cardano-prelude git |      ef87bb9 |
| # |                             Era |      babbage |
| # |             Delegation map size |            0 |
| # |          Starting UTxO set size |            0 |
| # |                Extra tx payload |          100 |
| # |                       Tx inputs |            2 |
| # |                      Tx Outputs |            2 |
| # |                             TPS |         15.0 |
| # |               Transaction count |         9000 |
| # |                   Plutus script |          --- |
| # |                        Machines |            6 |
| # |       Number of filters applied |            1 |
| # | Log text lines emitted per host | 15538.111111 |
| # |    Log objects emitted per host | 15503.111111 |
| # |   Log objects analysed per host | 3819.6111111 |
| # |                Host run time, s |      797.131 |
| # |          Host log line rate, Hz |       35.850 |
| # |      Total log objects analysed |        21349 |
| # |                     Run time, s |          394 |
| # |        Analysed run duration, s |          362 |
| # |             Run time efficiency |         0.91 |
| # |            Node start spread, s |         .026 |
| # |             Node stop spread, s |    3850.3233 |
| # |   Perf analysis start spread, s |            0 |
| # |    Perf analysis stop spread, s |         3850 |
| # |                  Slots analysed |          764 |
| # |                 Blocks analysed |           14 |
| # |                 Blocks rejected |            1 |

#+TITLE: 2023-07-07-09-37-55fda-trace-bench-bage-sup-prof, 2023-07-07-09-44-55fda-trace-bench-bage-sup-prof, 2023-07-07-10-55-55fda-trace-bench-bage-sup-prof
#+SUBTITLE: filters: unfiltered, slot range: raw(0-362, I 362 total) filtered(0-362, I 362 total), filtered 1.0
#+DATE: 2023-07-07 11:01:11 UTC
#+VERSION: locli 1.29 (55fda1)
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| ! |                   metric | average |    CoV |    min |    max | stddev |  range | precision |   size |
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| # |     Forge loop starts, # |  .90461 | .18263 | .71383 |   1.0  | .16521 | .28616 |      .0   |   3.0  |
| # |     Process CPU usage, % |  2.1031 | .08142 | 1.9098 | 2.2357 | .17124 | .32594 |      .0   |   3.0  |
| # |      RTS GC CPU usage, % |  .11338 | .16022 | .09353 | .12919 | .01816 | .03565 |      .0   |   3.0  |
| # | RTS Mutator CPU usage, % |  2.0567 | .07377 | 1.8875 | 2.1808 | .15173 | .29328 |      .0   |   3.0  |
| # |             Major GCs, # |  .03255 | .19436 | .02693 | .03940 | .00632 | .01246 |      .0   |   3.0  |
| # |             Minor GCs, # |  .69070 | .14628 | .57695 | .77002 | .10103 | .19307 |      .0   |   3.0  |
| # |           Kernel RSS, MB |  158.02 | .01674 | 155.71 | 160.91 | 2.6462 | 5.1939 |      .0   |   3.0  |
| # |        RTS heap size, MB |  9.3922 | .03358 | 9.0284 | 9.5879 | .31540 | .55951 |      .0   |   3.0  |
| # |  RTS live GC dateset, MB |  65.981 | .03145 | 64.094 | 68.205 | 2.0757 | 4.1102 |      .0   |   3.0  |
| # |     RTS alloc rate, MB/s |  21.631 | .14867 | 18.043 | 24.255 | 3.2160 | 6.2115 |      .0   |   3.0  |
| # |      Network reads, KB/s |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
| # |     Network writes, KB/s |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
| # |   Filesystem reads, KB/s |  .14298 | 1.7320 |   .0   | .42894 | .24764 | .42894 |      .0   |   3.0  |
| # |  Filesystem writes, KB/s |  .54581 | .23695 | .42488 | .68217 | .12933 | .25728 |      .0   |   3.0  |
| # |     CPU 85% spans, slots |  .33333 |   .0   | .33333 | .33333 |   .0   |   .0   |      .0   |   3.0  |
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| _ |                 nSamples |         |        |        |        |        |        |           |        |
| # |                     137> |         |        |        |        |        |        |           |        |

#+TITLE: 2023-07-07-10-55-55fda_variance_8.1.1
#+SUBTITLE: filters: unfiltered, slot range: raw(0-362, I 362 total) filtered(0-362, I 362 total), filtered 1.0
#+DATE: 2023-07-07 11:01:11 UTC
#+VERSION: locli 1.29 (55fda1)
|---+---------------------------------------+---------+-------+----------+--------------------------------------------------------------|
| ! |                             Parameter | time, % | range | alloc, % |                                              source location |
|---+---------------------------------------+---------+-------+----------+--------------------------------------------------------------|
| # |                              unquoted |     7.9 |   3.0 |      11. |                  src/Data/Aeson/Encoding/Builder.hs:114:1-47 |
| # |                            forMachine |     7.8 |   8.1 |      19. | src/Cardano/Node/Tracing/Tracers/Diffusion.hs:(34,5)-(37,37) |
| # |                                  text |     2.4 |   2.2 |      2.6 |                  src/Data/Aeson/Encoding/Builder.hs:110:1-49 |
| # |                                  fn_3 |     2.1 |   1.8 |      4.8 |                             src/Data/SOP/Classes.hs:147:1-55 |
| # |                       timeToTimeOfDay |     2.0 |   2.0 |      1.2 | lib/Data/Time/LocalTime/Internal/TimeOfDay.hs:(94,1)-(102,18 |
| # |                       codecEKGForward |     1.7 |   1.2 |      1.4 |          src/System/Metrics/Protocol/Codec.hs:(32,1)-(80,88) |
| # |                     runPeerWithSink.\ |     1.6 |   2.1 |      0.8 | src/Trace/Forward/Run/TraceObject/Forwarder.hs:(45,5)-(50,62 |
| # |                            formatTime |     1.5 |   0.8 |      1.4 |        lib/Data/Time/Format/Format/Class.hs:(331,1)-(336,57) |
| # |                             toBuilder |     1.4 |   2.0 |      0.9 |           src/Codec/CBOR/ByteArray/Sliced.hs:(87,1)-(100,31) |
| # |                                  MAIN |     1.4 |   0.5 |      0.1 |                                                    |
| # |                            qshowsPrec |     1.4 |   0.1 |      2.6 |                                  src/Quiet.hs:(62,1)-(63,32) |
| # |                              forHuman |     1.3 |   3.4 |      2.1 | src/Cardano/Node/Tracing/Tracers/Diffusion.hs:(38,5)-(39,57) |
| # |                         formatGeneral |     1.3 |   1.1 |      1.0 |          lib/Data/Time/Format/Format/Class.hs:(73,1)-(74,84) |
| # |               withTimeoutSerialNative |     1.3 |   1.0 |      0.2 |                           src/Network/Mux/Timeout.hs:67:1-54 |
| # |        machineFormatter'.\.machineObj |     1.3 |   0.7 |      0.7 |           src/Cardano/Logging/Formatter.hs:(156,17)-(162,60) |
| # | throwSocketErrorIfMinus1RetryMayBlock |     1.3 |   0.6 |      0.1 |                  Network/Socket/Internal.hs:(208,1)-(209,53) |
| # |                      psbUseAsSizedPtr |     1.2 |   0.5 |      0.0 |      src/Cardano/Crypto/PinnedSizedBytes.hs:(276,1)-(278,17) |
| # |                          stdoutThread |     1.2 |   0.1 |      0.2 |        src/Cardano/Logging/Tracer/Standard.hs:(79,1)-(82,17) |
| # |                                string |     1.2 |   0.3 |      1.0 |          src/Data/Aeson/Encoding/Builder.hs:(122,1)-(123,66) |
| # |                               hcliftA |     1.2 |   0.3 |      0.7 |                             src/Data/SOP/Classes.hs:317:1-50 |
| # |                 unsafeUseAsCStringLen |     1.2 |   0.0 |      0.0 |                           Data/ByteString/Unsafe.hs:285:1-88 |
| # |                                     . |     1.1 |   0.3 |      0.5 |                   src/Control/Tracer/Arrow.hs:(64,3)-(72,68) |
| # |                           readTBQueue |     1.1 |   0.1 |      0.2 |           Control/Concurrent/STM/TBQueue.hs:(121,1)-(141,18) |
| # |                                 trans |     1.1 |   0.3 |      0.5 |            src/Control/State/Transition/Extended.hs:416:1-36 |
| # |                       showHostAddress |     1.1 |   0.1 |      0.9 |                     Network/Socket/Info.hsc:(434,1)-(436,72) |
| # |        forwardFormatter'.\.machineObj |     1.1 |   0.1 |      1.1 |           src/Cardano/Logging/Formatter.hs:(113,17)-(119,60) |
| # |           withNamespaceConfig.mkTrace |     1.1 |   0.3 |      0.5 |        src/Cardano/Logging/Configuration.hs:(157,5)-(253,98) |
| # |                                 comma |     1.1 |   0.0 |      0.5 |                 src/Data/Aeson/Encoding/Internal.hs:276:1-35 |
| # |                             sampleAll |     1.1 |   0.0 |      0.6 |                           System/Metrics.hs:(599,1)-(606,35) |
| # |                                object |     1.0 |   0.1 |      0.6 |           src/Data/Aeson/Encoding/Builder.hs:(97,1)-(102,61) |
| # |                                 colon |     1.0 |   0.1 |      0.5 |                 src/Data/Aeson/Encoding/Internal.hs:277:1-35 |
| # |                      readProcNetInOut |     1.0 |   0.1 |      2.0 |        src/Cardano/Logging/Resources/Linux.hs:(87,1)-(95,31) |
| # |                      toLazyByteString |     0.6 |   0.5 |      2.8 |                  Data/ByteString/Builder.hs:(278,1)-(279,62) |
| # |                            encodeUtf8 |     0.5 |   0.9 |      1.3 |                   src/Data/Text/Encoding.hs:(462,1)-(477,37) |
| # |                getAlonzoScriptsNeeded |     0.4 |   0.5 |      1.4 |           src/Cardano/Ledger/Alonzo/UTxO.hs:(129,1)-(151,99) |
| # |                      babbageTxScripts |     0.4 |   0.3 |      1.5 |            src/Cardano/Ledger/Babbage/Tx.hs:(142,1)-(146,73) |
| # |                     hashToStringAsHex |     0.3 |   0.3 |      1.0 |                    src/Cardano/Crypto/Hash/Class.hs:254:1-49 |
| # |                        witsVKeyNeeded |     0.3 |   0.4 |      1.1 |    src/Cardano/Ledger/Alonzo/Rules/Utxow.hs:(433,1)-(487,19) |

jutaro commented 1 year ago

New tracing results (ghc 8.10.7) without profiling

Started with: make cls trace-bench-prof

#+TITLE: 2023-07-12-12-59-7dc86_variance_8.1.1
#+SUBTITLE: filters: unfiltered, slot range: raw(0-484, I 484 total) filtered(0-484, I 484 total), filtered 1.0
#+DATE: 2023-07-12 13:09:59 UTC
#+VERSION: locli 1.29 (7dc86f)
|---+---------------------------------+--------------|
| ! |                       Parameter |        Value |
|---+---------------------------------+--------------|
| # |                   Analysis date |   2023-07-12 |
| # |       Cluster system start date |   2023-07-12 |
| # |       Cluster system start time |     12:43:09 |
| # |                      Identifier |        8.1.1 |
| # |                       Run batch |        plain |
| # |            cardano-node version |        8.1.1 |
| # |     ouroboros-consensus version |      0.7.0.0 |
| # |       ouroboros-network version |      0.8.1.1 |
| # |     cardano-ledger-core version |      1.2.0.0 |
| # |             plutus-core version |      1.5.0.1 |
| # |          cardano-crypto version |        1.1.2 |
| # |         cardano-prelude version |      0.1.0.2 |
| # |                cardano-node git |      7dc86f7 |
| # |         ouroboros-consensus git |      143e9df |
| # |           ouroboros-network git |      0012bba |
| # |         cardano-ledger-core git |      6db84a7 |
| # |                 plutus-core git |      e42d1a0 |
| # |              cardano-crypto git |      6568a5e |
| # |             cardano-prelude git |      ef87bb9 |
| # |                             Era |      babbage |
| # |             Delegation map size |            0 |
| # |          Starting UTxO set size |            0 |
| # |                Extra tx payload |          100 |
| # |                       Tx inputs |            2 |
| # |                      Tx Outputs |            2 |
| # |                             TPS |         15.0 |
| # |               Transaction count |         9000 |
| # |                   Plutus script |          --- |
| # |                        Machines |            6 |
| # |       Number of filters applied |            1 |
| # | Log text lines emitted per host | 7590.3333333 |
| # |    Log objects emitted per host | 7559.3333333 |
| # |   Log objects analysed per host |       4519.0 |
| # |                Host run time, s |      483.328 |
| # |          Host log line rate, Hz |       15.617 |
| # |      Total log objects analysed |        26861 |
| # |                     Run time, s |          516 |
| # |        Analysed run duration, s |          484 |
| # |             Run time efficiency |         0.93 |
| # |            Node start spread, s |         .022 |
| # |             Node stop spread, s |      52.9958 |
| # |   Perf analysis start spread, s |            0 |
| # |    Perf analysis stop spread, s |           53 |
| # |                  Slots analysed |          451 |
| # |                 Blocks analysed |           15 |
| # |                 Blocks rejected |            0 |

#+TITLE: 2023-07-12-12-42-7dc86-trace-bench-bage-sup, 2023-07-12-12-51-7dc86-trace-bench-bage-sup, 2023-07-12-12-59-7dc86-trace-bench-bage-sup
#+SUBTITLE: filters: unfiltered, slot range: raw(0-484, I 484 total) filtered(0-484, I 484 total), filtered 1.0
#+DATE: 2023-07-12 13:09:59 UTC
#+VERSION: locli 1.29 (7dc86f)
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| ! |                   metric | average |    CoV |    min |    max | stddev |  range | precision |   size |
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| # |     Forge loop starts, # |    1.0  |   .0   |   1.0  |   1.0  |   .0   |   .0   |      .0   |   3.0  |
| # |     Process CPU usage, % |  1.0621 | .02585 | 1.0307 | 1.0818 | .02746 | .05108 |      .0   |   3.0  |
| # |      RTS GC CPU usage, % |  .08041 | .06275 | .07569 | .08573 | .00504 | .01004 |      .0   |   3.0  |
| # | RTS Mutator CPU usage, % |  1.0492 | .03004 | 1.0128 | 1.0684 | .03152 | .05559 |      .0   |   3.0  |
| # |             Major GCs, # |  .00871 | .10375 | .00770 | .00946 | .00090 | .00175 |      .0   |   3.0  |
| # |             Minor GCs, # |  .09200 | .02955 | .08995 | .09508 | .00271 | .00513 |      .0   |   3.0  |
| # |           Kernel RSS, MB |  88.379 | .00626 | 87.742 | 88.741 | .55329 | .99852 |      .0   |   3.0  |
| # |        RTS heap size, MB |  4.3751 | .03664 | 4.1901 | 4.4731 | .16033 | .28300 |      .0   |   3.0  |
| # |  RTS live GC dateset, MB |  43.910 | .00285 | 43.781 | 44.032 | .12525 | .25023 |      .0   |   3.0  |
| # |     RTS alloc rate, MB/s |  3.1171 | .02544 | 3.0508 | 3.2049 | .07931 | .15416 |      .0   |   3.0  |
| # |      Network reads, KB/s |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
| # |     Network writes, KB/s |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
| # |   Filesystem reads, KB/s |  .00102 | .86790 |   .0   | .00159 | .00089 | .00159 |      .0   |   3.0  |
| # |  Filesystem writes, KB/s |  .54478 | .06342 | .51567 | .58297 | .03455 | .06730 |      .0   |   3.0  |
| # |     CPU 85% spans, slots |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| _ |                 nSamples |         |        |        |        |        |        |           |        |
| # |                     8139 |         |        |        |        |        |        |           |        |

jutaro commented 1 year ago

Old tracing results (ghc 8.10.7) without profiling

Started with: make cls trace-bench-oldtracing

#+TITLE: 2023-07-12-14-49-7dc86_variance_8.1.1
#+SUBTITLE: filters: unfiltered, slot range: raw(0-285, I 285 total) filtered(0-285, I 285 total), filtered 1.0
#+DATE: 2023-07-12 14:56:44 UTC
#+VERSION: locli 1.29 (7dc86f)
|---+---------------------------------+--------------|
| ! |                       Parameter |        Value |
|---+---------------------------------+--------------|
| # |                   Analysis date |   2023-07-12 |
| # |       Cluster system start date |   2023-07-12 |
| # |       Cluster system start time |     13:32:08 |
| # |                      Identifier |        8.1.1 |
| # |                       Run batch |        plain |
| # |            cardano-node version |        8.1.1 |
| # |     ouroboros-consensus version |      0.7.0.0 |
| # |       ouroboros-network version |      0.8.1.1 |
| # |     cardano-ledger-core version |      1.2.0.0 |
| # |             plutus-core version |      1.5.0.1 |
| # |          cardano-crypto version |        1.1.2 |
| # |         cardano-prelude version |      0.1.0.2 |
| # |                cardano-node git |      7dc86f7 |
| # |         ouroboros-consensus git |      143e9df |
| # |           ouroboros-network git |      0012bba |
| # |         cardano-ledger-core git |      6db84a7 |
| # |                 plutus-core git |      e42d1a0 |
| # |              cardano-crypto git |      6568a5e |
| # |             cardano-prelude git |      ef87bb9 |
| # |                             Era |      babbage |
| # |             Delegation map size |            0 |
| # |          Starting UTxO set size |            0 |
| # |                Extra tx payload |          100 |
| # |                       Tx inputs |            2 |
| # |                      Tx Outputs |            2 |
| # |                             TPS |         15.0 |
| # |               Transaction count |         9000 |
| # |                   Plutus script |          --- |
| # |                        Machines |            6 |
| # |       Number of filters applied |            1 |
| # | Log text lines emitted per host |       6403.5 |
| # |    Log objects emitted per host |       6373.5 |
| # |   Log objects analysed per host | 3472.6111111 |
| # |                Host run time, s |       566.85 |
| # |          Host log line rate, Hz |       14.067 |
| # |      Total log objects analysed |        20015 |
| # |                     Run time, s |          401 |
| # |        Analysed run duration, s |          371 |
| # |             Run time efficiency |         0.92 |
| # |            Node start spread, s |          .25 |
| # |             Node stop spread, s |          .04 |
| # |   Perf analysis start spread, s |            0 |
| # |    Perf analysis stop spread, s |            0 |
| # |                  Slots analysed |          536 |
| # |                 Blocks analysed |           15 |
| # |                 Blocks rejected |            0 |

#+TITLE: 2023-07-12-13-31-7dc86-trace-bench-oldtracing-bage-sup, 2023-07-12-14-43-7dc86-trace-bench-oldtracing-bage-sup, 2023-07-12-14-49-7dc86-trace-bench-oldtracing-bage-sup
#+SUBTITLE: filters: unfiltered, slot range: raw(0-285, I 285 total) filtered(0-285, I 285 total), filtered 1.0
#+DATE: 2023-07-12 14:56:44 UTC
#+VERSION: locli 1.29 (7dc86f)
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| ! |                   metric | average |    CoV |    min |    max | stddev |  range | precision |   size |
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| # |     Forge loop starts, # |  .95230 | .08675 | .85690 |   1.0  | .08261 | .14309 |      .0   |   3.0  |
| # |     Process CPU usage, % |  1.2797 | .35825 | .75070 | 1.5609 | .45847 | .81019 |      .0   |   3.0  |
| # |      RTS GC CPU usage, % |  .02829 | .60842 | .00859 | .04042 | .01721 | .03183 |      .0   |   3.0  |
| # | RTS Mutator CPU usage, % |  1.2517 | .35396 | .74036 | 1.5215 | .44306 | .78122 |      .0   |   3.0  |
| # |             Major GCs, # |  .00972 | .12023 | .00901 | .01107 | .00116 | .00205 |      .0   |   3.0  |
| # |             Minor GCs, # |  .08356 | .02556 | .08119 | .08533 | .00213 | .00414 |      .0   |   3.0  |
| # |           Kernel RSS, MB |  91.732 | .04804 | 86.666 | 94.687 | 4.4072 | 8.0207 |      .0   |   3.0  |
| # |        RTS heap size, MB |  2.8023 | .02406 | 2.7358 | 2.8706 | .06742 | .13480 |      .0   |   3.0  |
| # |  RTS live GC dateset, MB |  42.074 | .00666 | 41.817 | 42.373 | .28025 | .55569 |      .0   |   3.0  |
| # |     RTS alloc rate, MB/s |  2.9270 | .03350 | 2.8155 |   3.0  | .09807 | .18443 |      .0   |   3.0  |
| # |      Network reads, KB/s |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
| # |     Network writes, KB/s |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
| # |   Filesystem reads, KB/s |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
| # |  Filesystem writes, KB/s |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
| # |     CPU 85% spans, slots |    .0   |   NAN  |   .0   |   .0   |   .0   |   .0   |      .0   |   3.0  |
|---+--------------------------+---------+--------+--------+--------+--------+--------+-----------+--------|
| _ |                 nSamples |         |        |        |        |        |        |           |        |
| # |                     9678 |         |        |        |        |        |        |           |        |

jutaro commented 1 year ago

As an intermediate conclusion, in terms of performance old tracing and new tracing seem to be par to par, which is quite a good result when we look at the additional work new tracing has to do. A real bench-marking run on a cluster may show other results, and we may then come back to optimizing, but for the moment the results are good enough to put them in a pull request.