search

hyperledger / caliper

A blockchain benchmark framework to measure performance of multiple blockchain solutions https://wiki.hyperledger.org/display/caliper
https://hyperledger.github.io/caliper/
Apache License 2.0
650 stars 402 forks source link

Default observer resets stats while output is still accumulating #1446

Open davidkel opened 2 years ago

davidkel commented 2 years ago

As an example 

2022.09.06-03:53:25.469 info  [caliper] [worker-orchestrator]   250 workers prepared, progressing to test phase.
2022.09.06-03:53:25.470 info  [caliper] [round-orchestrator]    Monitors successfully started
2022.09.06-03:53:30.515 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 11698 Succ: 3828 Fail:0 Unfinished:7870
2022.09.06-03:53:35.510 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 26633 Succ: 8209 Fail:0 Unfinished:18424
2022.09.06-03:53:40.494 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 41656 Succ: 12570 Fail:0 Unfinished:29086
2022.09.06-03:53:45.495 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 56686 Succ: 16912 Fail:0 Unfinished:39774
2022.09.06-03:53:50.508 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 71601 Succ: 21143 Fail:0 Unfinished:50458
2022.09.06-03:53:55.499 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 86616 Succ: 25349 Fail:0 Unfinished:61267
2022.09.06-03:54:00.506 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 101534 Succ: 29550 Fail:0 Unfinished:71984
2022.09.06-03:54:05.523 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 115220 Succ: 33571 Fail:0 Unfinished:81649
2022.09.06-03:54:10.527 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 128540 Succ: 37735 Fail:0 Unfinished:90805
2022.09.06-03:54:15.575 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 138526 Succ: 41873 Fail:827 Unfinished:95826
2022.09.06-03:54:20.548 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 145678 Succ: 46018 Fail:2952 Unfinished:96708
2022.09.06-03:54:25.546 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 152264 Succ: 50366 Fail:5062 Unfinished:96836
2022.09.06-03:54:30.583 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 158302 Succ: 54698 Fail:7187 Unfinished:96417
2022.09.06-03:54:35.538 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 164136 Succ: 59095 Fail:9274 Unfinished:95767
2022.09.06-03:54:40.568 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 169791 Succ: 63461 Fail:11382 Unfinished:94948
2022.09.06-03:54:45.529 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 175499 Succ: 67891 Fail:13478 Unfinished:94130
2022.09.06-03:54:50.544 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 180868 Succ: 72259 Fail:15682 Unfinished:92927
2022.09.06-03:54:55.498 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 183458 Succ: 72508 Fail:21331 Unfinished:89619
2022.09.06-03:55:00.490 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 101346 Succ: 34806 Fail:23570 Unfinished:42970
2022.09.06-03:55:05.490 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 81063 Succ: 24673 Fail:25943 Unfinished:30447
2022.09.06-03:55:10.493 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 82158 Succ: 23843 Fail:29235 Unfinished:29080
2022.09.06-03:55:15.490 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 74074 Succ: 19758 Fail:30579 Unfinished:23737
2022.09.06-03:55:20.490 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 79682 Succ: 23733 Fail:31133 Unfinished:24816
2022.09.06-03:55:25.490 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 80554 Succ: 26418 Fail:31319 Unfinished:22817
2022.09.06-03:55:30.491 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 77351 Succ: 39248 Fail:30737 Unfinished:7366
2022.09.06-03:55:35.486 info  [caliper] [default-observer]      Resetting txCount indicator count
2022.09.06-03:55:40.483 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 6576 Succ: 2899 Fail:1845 Unfinished:1832
2022.09.06-03:55:45.484 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 9271 Succ: 4023 Fail:2994 Unfinished:2254
2022.09.06-03:55:50.484 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 3996 Succ: 1724 Fail:1380 Unfinished:892
2022.09.06-03:55:55.485 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 9126 Succ: 4049 Fail:3428 Unfinished:1649
2022.09.06-03:56:00.486 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 5872 Succ: 2599 Fail:2315 Unfinished:958
2022.09.06-03:56:05.486 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 8465 Succ: 3765 Fail:3559 Unfinished:1141
2022.09.06-03:56:10.488 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 18231 Succ: 8094 Fail:8073 Unfinished:2064
2022.09.06-03:56:15.486 info  [caliper] [default-observer]      Resetting txCount indicator count
2022.09.06-03:56:20.493 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 35944 Succ: 16010 Fail:18872 Unfinished:1062
2022.09.06-03:56:25.487 info  [caliper] [default-observer]      Resetting txCount indicator count
2022.09.06-03:56:30.494 info  [caliper] [default-observer]      Resetting txCount indicator count
2022.09.06-03:56:35.506 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 127059 Succ: 55687 Fail:70819 Unfinished:553
2022.09.06-03:56:40.500 info  [caliper] [default-observer]      Resetting txCount indicator count
2022.09.06-03:56:45.491 info  [caliper] [default-observer]      Resetting txCount indicator count
2022.09.06-03:56:50.513 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 125148 Succ: 54803 Fail:69849 Unfinished:496
2022.09.06-03:56:55.507 info  [caliper] [default-observer]      Resetting txCount indicator count
2022.09.06-03:57:00.510 info  [caliper] [default-observer]      [create-asset-100 Round 0 Transaction Info] - Submitted: 124489 Succ: 54511 Fail:69509 Unfinished:469
2022.09.06-03:57:05.500 info  [caliper] [default-observer]      Resetting txCount indicator count
2022.09.06-03:57:10.504 info  [caliper] [default-observer]      Resetting txCount indicator count
2022.09.06-03:57:15.506 info  [caliper] [default-observer]      Resetting txCount indicator count
2022.09.06-03:57:20.501 info  [caliper] [default-observer]      Resetting txCount indicator count
2022.09.06-03:57:25.489 info  [caliper] [default-observer]      Resetting txCount indicator count
2022.09.06-03:57:30.490 info  [caliper] [default-observer]      Resetting txCount indicator count
2022.09.06-03:57:35.490 info  [caliper] [default-observer]      Resetting txCount indicator count
2022.09.06-03:57:41.558 info  [caliper] [default-observer]      Resetting txCount indicator count
2022.09.06-03:57:41.560 info  [caliper] [report-builder]        ### Test result ###
2022.09.06-03:57:41.570 info  [caliper] [report-builder]
+------------------+--------+--------+-----------------+-----------------+-----------------+-----------------+------------------+
| Name             | Succ   | Fail   | Send Rate (TPS) | Max Latency (s) | Min Latency (s) | Avg Latency (s) | Throughput (TPS) |
|------------------|--------|--------|-----------------|-----------------|-----------------|-----------------|------------------|
| create-asset-100 | 100290 | 103757 | 1079.5          | 127.88          | 0.05            | 29.23           | 816.5            |
+------------------+--------+--------+-----------------+-----------------+-----------------+-----------------+------------------+

It doesn't affect the final output. I think I've also seen the values reset with no message Resetting txCount indicator count and this appears to be in line when lots of failures occur, not sure.

The reset request can be sent from all workers to the manager yet in normal cases only a single reset is logged (which is interesting) but given a reset is sent by all workers if some workers finish quicker than others a reset is sent but more work could still come in from other workers which means the default observer is being told to reset incorrectly.

This reset message appears to only be between the default observer and the worker, so I have no idea why it's actually needed