IO: CoroutineScheduler: high CPU usage for Worker.cpuWorkerIdle on an idle system

[fvasco]

I updated this library to version 0.25.0, I detected an abnormal CPU usage on my laptop with "AMD PRO A12-8800B R7, 12 Compute Cores 4C+8G" cpu.

VisualVM shows 48% of CPU usage is for

"CoroutineScheduler-worker-4" #113 daemon prio=5 os_prio=0 tid=0x00007f29cc009000 nid=0xc5 runnable  [0x00007f29949f2000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.Thread.yield([email protected]/Native Method)
	at kotlinx.coroutines.experimental.scheduling.CoroutineScheduler$Worker.cpuWorkerIdle(CoroutineScheduler.kt:783)
	at kotlinx.coroutines.experimental.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:693)

16% is

"CoroutineScheduler-worker-5" #117 daemon prio=5 os_prio=0 tid=0x00007f29d8002000 nid=0x100 runnable  [0x00007f29c0bbb000]
   java.lang.Thread.State: RUNNABLE
	at kotlinx.coroutines.experimental.scheduling.CoroutineScheduler.parkedWorkersStackPop(CoroutineScheduler.kt:982)
	at kotlinx.coroutines.experimental.scheduling.CoroutineScheduler.tryUnpark(CoroutineScheduler.kt:395)
	at kotlinx.coroutines.experimental.scheduling.CoroutineScheduler.requestCpuWorker(CoroutineScheduler.kt:366)
	at kotlinx.coroutines.experimental.scheduling.CoroutineScheduler.access$requestCpuWorker(CoroutineScheduler.kt:60)
	at kotlinx.coroutines.experimental.scheduling.CoroutineScheduler$Worker.beforeTask(CoroutineScheduler.kt:727)
	at kotlinx.coroutines.experimental.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:703)

12% is

"CoroutineScheduler-worker-3" #77 daemon prio=5 os_prio=0 tid=0x00007f29d0003000 nid=0x64 runnable  [0x00007f29947ef000]
   java.lang.Thread.State: RUNNABLE
	at kotlinx.coroutines.experimental.scheduling.CoroutineScheduler$Worker.findTask(CoroutineScheduler.kt:902)
	at kotlinx.coroutines.experimental.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:689)

This has happened after some idle hours.

openjdk version "10.0.1" 2018-04-17
OpenJDK Runtime Environment (build 10.0.1+10-Debian-2)
OpenJDK 64-Bit Server VM (build 10.0.1+10-Debian-2, mixed mode)

[qwwdfsad]

Thanks for the report, I'll take a look.
Could you please also attach a jstack result for your application?
Are you using CoroutineScheduler only as IO or as a main scheduler as well?

[fvasco]

I am using the default scheduler and I switch on IO for blocking methods (ie: JDBC invocations).
Error detected on Java 10

first-jstack.gz
jstack.gz

[qwwdfsad]

VisualVM shows 48% of CPU usage

Let's clarify: your application is CPU-idle and does I/O, you've profiled it with visualvm (btw, sampler or profiler mode?) and noticed that 48% of execution time is spent within CoroutineScheduler, right?

Is it a CPU usage of visualvm profile or 48% of actual CPU consumption (which is shown by top, htop or Mac OS X activity monitor)? Have you noticed it accidentally or it's a significant CPU-burner?

In general, if application does only I/O (which doesn't contribute anything to CPU consumption), then it's perfectly fine if most of the application CPU usage (which is a little in comparison with available CPU on the machine) is spent withing scheduler, as I/O code doesn't end up in CPU profile. But if your application is completely idle or this is 48% of real CPU usage, then it is a serious problem.

[fvasco]

The profiled server is in development mode on my laptop.
I used the VisualVM's "CPU sampler".
There is no load on server, I started it and no more; it replies only to docker healthcheck, so the expected load is near 1% of CPU.

If I pause the docker container then the CPU goes low, if I unpause the conteiner all CPU's cores go to 100% (measured with top on Linux).

[fvasco]

Profile result attached
Used async-profiler-1.4-linux-x64.tar.gz

./profiler.sh -d 30 1

profiled.gz

[adamp]

Possibly related to #524?

[GeoffreyMetais]

Stack from Android (when IO usage caused the wjole app to freeze)

https://pastebin.com/iBiqKPHF

Hope it will help.