[IGNITE-5573] Yardstick: Incorrect actual warmup and duration when test with pds and many caches

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 2.1
• Component/s: yardstick
• Assignee: Unassigned
• Reporter: Ksenia Rybakova
• Created: 21/Jun/17 14:59
• Updated: 21/Jun/17 15:01

Description

Load config:

• CacheRandomOperation benchmak
• 5 driver nodes
• 12 server nodes (1 per host)
• 14 phisical caches + 50 groups with 500 logical caches (10 per group)
• preloading amount 10K, key range 20K
• warmup time 300s
• duration 1800s

But according to driver logs actual warmup time and duration are incorrect (or it's just logging problem)

<16:15:35><main><yardstick> Preload logger was started.
...
<16:27:19><main><yardstick> Preload logger was stopped.
<16:27:19><main><yardstick> Probe writer is not configured (using default CSV writer)
<16:27:19><main><yardstick> ThroughputLatencyProbe is started.
<16:27:19><main><yardstick> DStatProbe is started. Command: 'dstat -m --all --noheaders --noupdate 1'
<16:27:19><main><yardstick> PercentileProbe is started.
<16:27:19><main><yardstick> Starting warmup.
...
<17:02:09><benchmark-worker-49><yardstick> Starting main test (warmup finished).
<17:02:09><benchmark-worker-22><yardstick> Starting iteration: 18
<17:02:09><benchmark-worker-59><yardstick> Starting iteration: 10
<17:02:09><benchmark-worker-54><yardstick> Starting iteration: 9
<17:02:09><benchmark-worker-11><yardstick> Starting iteration: 25
<17:02:09><benchmark-worker-33><yardstick> Starting iteration: 27
<17:02:09><benchmark-worker-4><yardstick> Starting iteration: 23
<17:02:09><benchmark-worker-42><yardstick> Starting iteration: 34
<17:02:09><benchmark-worker-35><yardstick> Starting iteration: 36
<17:02:09><benchmark-worker-45><yardstick> Starting iteration: 41
<17:02:09><benchmark-worker-58><yardstick> Starting iteration: 1
<17:02:09><benchmark-worker-12><yardstick> Starting iteration: 44
<17:02:09><benchmark-worker-19><yardstick> Starting iteration: 46
<17:02:09><benchmark-worker-32><yardstick> Starting iteration: 47
<17:02:09><benchmark-worker-9><yardstick> Starting iteration: 48
<17:02:09><benchmark-worker-6><yardstick> Starting iteration: 39
<17:02:09><benchmark-worker-36><yardstick> Starting iteration: 52
<17:02:09><benchmark-worker-47><yardstick> Starting iteration: 54
<17:02:09><benchmark-worker-62><yardstick> Starting iteration: 56
<17:02:09><benchmark-worker-50><yardstick> Starting iteration: 57
<17:02:09><benchmark-worker-56><yardstick> Starting iteration: 58
<17:02:09><benchmark-worker-10><yardstick> Starting iteration: 20
<17:02:09><benchmark-worker-63><yardstick> Starting iteration: 24
<17:02:09><benchmark-worker-3><yardstick> Starting iteration: 59
<17:02:09><benchmark-worker-43><yardstick> Starting iteration: 60
<17:02:09><benchmark-worker-44><yardstick> Starting iteration: 61
<17:02:09><benchmark-worker-28><yardstick> Starting iteration: 62
<17:02:09><benchmark-worker-24><yardstick> Starting iteration: 63
<17:02:09><benchmark-worker-51><yardstick> Starting iteration: 21
<17:02:09><benchmark-worker-38><yardstick> Starting iteration: 22
<17:02:09><benchmark-worker-0><yardstick> Starting iteration: 7
<17:02:09><benchmark-worker-49><yardstick> Starting iteration: 8
<17:02:09><benchmark-worker-27><yardstick> Starting iteration: 5
<17:02:09><benchmark-worker-29><yardstick> Starting iteration: 3
<17:02:09><benchmark-worker-53><yardstick> Starting iteration: 15
<17:02:09><benchmark-worker-31><yardstick> Starting iteration: 2
<17:02:09><benchmark-worker-46><yardstick> Starting iteration: 11
<17:02:09><benchmark-worker-23><yardstick> Starting iteration: 12
<17:02:09><benchmark-worker-52><yardstick> Starting iteration: 4
<17:02:09><benchmark-worker-16><yardstick> Starting iteration: 16
<17:02:09><benchmark-worker-30><yardstick> Starting iteration: 19
<17:02:09><benchmark-worker-57><yardstick> Starting iteration: 6
<17:02:09><benchmark-worker-8><yardstick> Starting iteration: 17
<17:02:09><benchmark-worker-41><yardstick> Starting iteration: 13
<17:02:09><benchmark-worker-7><yardstick> Starting iteration: 14
<17:02:09><benchmark-worker-18><yardstick> Starting iteration: 64
<17:02:09><benchmark-worker-21><yardstick> Starting iteration: 37
<17:02:09><benchmark-worker-15><yardstick> Starting iteration: 55
<17:02:09><benchmark-worker-48><yardstick> Starting iteration: 53
<17:02:09><benchmark-worker-5><yardstick> Starting iteration: 51
<17:02:09><benchmark-worker-39><yardstick> Starting iteration: 50
<17:02:09><benchmark-worker-13><yardstick> Starting iteration: 49
<17:02:09><benchmark-worker-14><yardstick> Starting iteration: 45
<17:02:09><benchmark-worker-40><yardstick> Starting iteration: 38
<17:02:09><benchmark-worker-55><yardstick> Starting iteration: 42
<17:02:09><benchmark-worker-34><yardstick> Starting iteration: 43
<17:02:09><benchmark-worker-2><yardstick> Starting iteration: 40
<17:02:09><benchmark-worker-26><yardstick> Starting iteration: 35
<17:02:09><benchmark-worker-1><yardstick> Starting iteration: 31
<17:02:09><benchmark-worker-61><yardstick> Starting iteration: 32
<17:02:09><benchmark-worker-17><yardstick> Starting iteration: 33
<17:02:09><benchmark-worker-25><yardstick> Starting iteration: 29
<17:02:09><benchmark-worker-37><yardstick> Starting iteration: 30
<17:02:09><benchmark-worker-60><yardstick> Starting iteration: 28
<17:02:09><benchmark-worker-20><yardstick> Starting iteration: 26
<17:02:10><probe-dump-thread><yardstick> ThroughputLatencyProbe results will be saved to: results-20170621-161454/0-172.25.1.31
<17:02:10><probe-dump-thread><yardstick> DStatProbe results will be saved to: results-20170621-161454/0-172.25.1.31
...
Finishing main test [ts=1498054591988, date=Wed Jun 21 17:16:31 MSK 2017]

Also iterations in log are out of order.