search

dotnet / crank

Benchmarking infrastructure for applications
MIT License
978 stars 105 forks source link

Load stuck on stopping #200

Closed sebastienros closed 1 year ago

sebastienros commented 3 years ago 
[02:57:30.349] Running job 'load' (267)
[02:57:30.349] Starting -> Running
[02:57:30.349] Starting counters
[02:57:30.349] Starting event pipe session
[02:57:30.349] IPC endpoint not available, retrying...
[02:57:30.349] Process started: 12496
[02:57:30.386] WRK Client
[02:57:30.386] args: -c 256 http://10.0.0.102:5000/plaintext --latency -d 15s -w 0s -t 32 --header Accept:text/plain,text/html;q=0.9,application/xhtml+xml;q=0.9,application/xml;q=0.8,*/*;q=0.7 -s scripts/pipeline.lua -- 16
[02:57:30.450] Starting event pipe session
[02:57:30.450] Event pipe session started
[02:57:30.515] Measuring first request ... 71 ms
[02:57:30.539] > wrk -d 15s -c 256 http://10.0.0.102:5000/plaintext --latency -t 32 --header Accept:text/plain,text/html;q=0.9,application/xhtml+xml;q=0.9,application/xml;q=0.8,*/*;q=0.7 -s scripts/pipeline.lua -- 16
[02:57:30.539] [STDERR] ##ChildProcessId:12513
[02:57:30.539] Tracking child process id: 12513
[02:57:30.550] Event pipe source created
[02:57:30.550] Processing event pipe source (load)...
[02:57:31.383] Processing job 'load' (267) in state Running
[02:57:32.383] Processing job 'load' (267) in state Running
[02:57:33.384] Processing job 'load' (267) in state Running
[02:57:34.384] Processing job 'load' (267) in state Running
[02:57:35.382] Processing job 'load' (267) in state Running
[02:57:36.383] Processing job 'load' (267) in state Running
[02:57:37.383] Processing job 'load' (267) in state Running
[02:57:38.385] Processing job 'load' (267) in state Running
[02:57:39.385] Processing job 'load' (267) in state Running
[02:57:40.385] Processing job 'load' (267) in state Running
[02:57:41.386] Processing job 'load' (267) in state Running
[02:57:42.387] Processing job 'load' (267) in state Running
[02:57:43.387] Processing job 'load' (267) in state Running
[02:57:44.387] Processing job 'load' (267) in state Running
[02:57:45.386] Processing job 'load' (267) in state Running
[02:57:45.760] Running 15s test @ http://10.0.0.102:5000/plaintext
[02:57:45.760]   32 threads and 256 connections
[02:57:45.760]   Thread Stats   Avg      Stdev     Max   +/- Stdev
[02:57:45.760]     Latency   669.64us    1.78ms  52.42ms   84.44%
[02:57:45.760]     Req/Sec   275.67k    27.95k  545.94k    82.84%
[02:57:45.760]   Latency Distribution
[02:57:45.760]      50%  289.00us
[02:57:45.760]      75%  443.00us
[02:57:45.760]      90%    9.98ms
[02:57:45.760]      99%    0.00us
[02:57:45.760]   132675032 requests in 15.10s, 15.57GB read
[02:57:45.760] Requests/sec: 8786818.17
[02:57:45.760] Transfer/sec:      1.03GB
[02:57:45.878] Event pipe source stopped (load)
[02:57:45.878] Stopping event pipe session (load)...
[02:57:46.387] Processing job 'load' (267) in state Running
[02:57:46.391] Process has exited (0)
[02:57:46.391] Running -> Stopped
[02:57:46.655] Driver stopping job '267'
[02:57:47.387] Processing job 'load' (267) in state Stopped
[02:57:47.387] Job 'load' (267) has stopped, waiting for the driver to delete it
[02:57:47.391] Process has exited (0)
[02:57:47.977] Driver deleting job '267'
[02:57:48.386] Processing job 'load' (267) in state Deleting
[02:57:48.386] Deleting job 'load' (267)
[02:57:48.386] Stopping heartbeat (load)... Success!
[02:57:48.386] Stopping counters event pipes for job 'load' (267)
[02:57:48.386] [WARNING] No event source open for job 'load' (267)
[02:57:48.386] Process stopped (Deleting)
[02:57:48.386] Deleting directory '/tmp/benchmarks-agent/benchmarks-server-1/mjmrkhv2.enq'
[02:57:48.434] SUCCESS
[02:57:48.434] Deleting -> Deleted
[02:57:49.435] All jobs in group are finished
[03:00:03.499] Processing job 'load' (268) in state New
[03:00:03.499] Acquiring Job 'load' (268)
[03:00:03.499] Checking requirements...
[03:00:03.499] Found source folder: /tmp/benchmarks-agent/benchmarks-server-1/bombardier
[03:00:03.499] New -> Initializing
[03:00:04.503] Processing job 'load' (268) in state Waiting
[03:00:04.503] Starting job 'load' (268)
[03:00:04.503] Waiting -> Starting
[03:00:04.503] Benchmarked Application in /tmp/benchmarks-agent/benchmarks-server-1/bombardier/crank/src/Microsoft.Crank.Jobs.Bombardier
[03:00:04.503] Skipping build step, reusing previous build
[03:00:04.503] Invoking executable: /tmp/benchmarks-agent/benchmarks-server-1/bombardier/crank/src/Microsoft.Crank.Jobs.Bombardier/published/Microsoft.Crank.Jobs.Bombardier
[03:00:04.503]   Arguments:  -c 256 -w 15 -d 15 -n 0 --insecure -l  --fasthttp    http://10.0.0.102:8080/?s=102400
[03:00:04.503]   Working directory: /tmp/benchmarks-agent/benchmarks-server-1/bombardier/crank/src/Microsoft.Crank.Jobs.Bombardier/published
[03:00:04.504] Starting counters
[03:00:04.504] Starting event pipe session
[03:00:04.504] IPC endpoint not available, retrying...
[03:00:04.504] Process started: 12653
[03:00:04.599] Bombardier Client
[03:00:04.599] Ready state detected, application is now running...
[03:00:04.599] Running job 'load' (268)
[03:00:04.599] Starting -> Running
[03:00:04.599] args: -c 256 -w 15 -d 15 -n 0 --insecure -l --fasthttp http://10.0.0.102:8080/?s=102400
[03:00:04.604] Starting event pipe session
[03:00:04.605] Event pipe session started
[03:00:04.801] Measuring first request ... 198 ms
[03:00:04.808] Setting execute permission on executable /tmp/.crank/1.2.5/bombardier-linux-amd64
[03:00:04.814] > bombardier  -d 15s -c 256 --insecure -l --fasthttp http://10.0.0.102:8080/?s=102400 --print r --format json
[03:00:04.906] Event pipe source created
[03:00:04.906] Processing event pipe source (load)...
[03:00:06.503] Processing job 'load' (268) in state Running
[03:00:07.503] Processing job 'load' (268) in state Running
[03:00:08.503] Processing job 'load' (268) in state Running
[03:00:09.504] Processing job 'load' (268) in state Running
[03:00:10.504] Processing job 'load' (268) in state Running
[03:00:11.504] Processing job 'load' (268) in state Running
[03:00:12.503] Processing job 'load' (268) in state Running
[03:00:13.501] Processing job 'load' (268) in state Running
[03:00:14.502] Processing job 'load' (268) in state Running
[03:00:15.502] Processing job 'load' (268) in state Running
[03:00:16.503] Processing job 'load' (268) in state Running
[03:00:17.503] Processing job 'load' (268) in state Running
[03:00:18.504] Processing job 'load' (268) in state Running
[03:00:19.504] Processing job 'load' (268) in state Running
[03:00:19.838] > bombardier  -d 15s -c 256 --insecure -l --fasthttp http://10.0.0.102:8080/?s=102400 --print r --format json
[03:00:19.839] [STDERR] ##ChildProcessId:12713
[03:00:19.839] Tracking child process id: 12713
[03:00:20.503] Processing job 'load' (268) in state Running
[03:00:21.503] Processing job 'load' (268) in state Running
[03:00:22.504] Processing job 'load' (268) in state Running
[03:00:23.504] Processing job 'load' (268) in state Running
[03:00:24.503] Processing job 'load' (268) in state Running
[03:00:25.503] Processing job 'load' (268) in state Running
[03:00:26.504] Processing job 'load' (268) in state Running
[03:00:27.504] Processing job 'load' (268) in state Running
[03:00:28.503] Processing job 'load' (268) in state Running
[03:00:29.503] Processing job 'load' (268) in state Running
[03:00:30.504] Processing job 'load' (268) in state Running
[03:00:31.504] Processing job 'load' (268) in state Running
[03:00:32.501] Processing job 'load' (268) in state Running
[03:00:33.502] Processing job 'load' (268) in state Running
[03:00:34.502] Processing job 'load' (268) in state Running
[03:00:34.542] [Heartbeat] Driver didn't communicate for 00:00:10. Halting job 'load' (268).
[03:00:34.542] Running -> Stopping
[03:00:34.859] {"spec":{"numberOfConnections":256,"testType":"timed","testDurationSeconds":15,"method":"GET","url":"http://10.0.0.102:8080/?s=102400","body":"","stream":false,"timeoutSeconds":2,"client":"fasthttp"},"result":{"bytesRead":57483101027,"bytesWritten":40366368,"timeTakenSeconds":15.005352948,"req1xx":0,"req2xx":560644,"req3xx":0,"req4xx":0,"req5xx":0,"others":0,"latency":{"mean":6843.726380733585,"stddev":1950.5619881856924,"max":237844,"percentiles":{"50":6728,"75":7658,"90":8674,"95":9518,"99":17478}},"rps":{"mean":37377.52365802061,"stddev":3409.2461328498744,"max":44711.50203389822,"percentiles":{"50":37564.101564,"75":39599.192176,"90":41253.698394,"95":42025.545228,"99":43438.934317}}}}
[03:00:35.010] Event pipe source stopped (load)
[03:00:35.010] Stopping event pipe session (load)...
[03:00:35.503] Processing job 'load' (268) in state Stopping
[03:00:35.503] Stopping job 'load' (268)
[03:00:35.503] Stopping heartbeat (load)... Success!
[03:00:35.503] Stopping counters event pipes for job 'load' (268)
[03:00:35.503] Counters stopped for job 'load' (268)
[03:00:35.503] Process stopped (Stopping)
[03:00:36.503] Processing job 'load' (268) in state Stopping
[03:00:36.503] Stopping job 'load' (268)
[03:00:37.504] Processing job 'load' (268) in state Stopping
[03:00:37.504] Stopping job 'load' (268)
[03:00:38.504] Processing job 'load' (268) in state Stopping
[03:00:38.504] Stopping job 'load' (268)
zhenlei520 commented 2 years ago

I also encountered this problem. Is there a solution for this?

sebastienros commented 1 year ago

Fixed