Constant disk I/O and CPU usage in steady state

[BardurArantsson]

Hi,

I'm seeing a weird issue with a mill build while mill should be doing nothing, namely:

• Constant I/O (writes) to the tune of about 40KiB/s (as reported by iotop).
• Constant CPU usage at about 100%-150%.

Here's some output from iotop --batch -o -p <mill-pid> -t -a:

    TIME    TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN      IO    COMMAND
08:17:00  118012 be/4 xx            0.00 B    352.00 K  ?unavailable?  java -DMILL_CLASSPATH=/home/xxxxxx/.cache/mill/download/0.12.3 -Djna.nosys=true -cp /home/xxxxxx/.cache/mill/download/0.12.3 mill.runner.client.MillClientMain -D mill.main.cli=./mill -w runBackground [TermInfoPropaga]
08:17:01 Total DISK READ :       0.00 B/s | Total DISK WRITE :      35.98 K/s
08:17:01 Actual DISK READ:       0.00 B/s | Actual DISK WRITE:     159.90 K/s
    TIME    TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN      IO    COMMAND
08:17:01  118012 be/4 xx            0.00 B    388.00 K  ?unavailable?  java -DMILL_CLASSPATH=/home/xxxxxx/.cache/mill/download/0.12.3 -Djna.nosys=true -cp /home/xxxxxx/.cache/mill/download/0.12.3 mill.runner.client.MillClientMain -D mill.main.cli=./mill -w runBackground [TermInfoPropaga]
08:17:02 Total DISK READ :       0.00 B/s | Total DISK WRITE :      39.94 K/s
08:17:02 Actual DISK READ:       0.00 B/s | Actual DISK WRITE:      39.94 K/s
    TIME    TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN      IO    COMMAND
08:17:02  118012 be/4 xx            0.00 B    428.00 K  ?unavailable?  java -DMILL_CLASSPATH=/home/xxxxxx/.cache/mill/download/0.12.3 -Djna.nosys=true -cp /home/xxxxxx/.cache/mill/download/0.12.3 mill.runner.client.MillClientMain -D mill.main.cli=./mill -w runBackground [TermInfoPropaga]

Which shows that it's generating about ~50KiB of writes per second. (Note that the '-a' option for iotop shows accumulated usage.)

Unfortunately, I'm not at liberty to share the actual build, but I don't think I'm doing anything particularly advanced/odd. It's a pretty small and simple Scala backend + Scala.js frontend build.

Does anyone have ideas for how to get more debugging info to properly track this issue down?

[lihaoyi]

@BardurArantsson could you hook up JProfiler to your MillServerMain process and upload a snapshot for me to look at?

[BardurArantsson]

(I have no idea whether the AtomicReference bit is necessary, but it probably can't hurt :) )

[lihaoyi]

@BardurArantsson seems reasonable. Not sure why writing a file 10 times a second on your machine is using 1 whole CPU, but maybe you have some antivirus stuff going on or something causing writes to be expensive.

Feel free to send a PR once you've tested that it works on your machine

[BardurArantsson]

No antivirus or anything like that. It's a pretty bog standard Arch Linux running on an SSD.

Can you explain how the file that's being written to is tracked by the rest of Mill? It is via the usual change detection machinery that e.g. Task uses? If so there may be something off there if it does lots of upstream work for a file whose contents actually haven't changed.

(Maybe there could be some issue where it's seeing a partially written file -- which is a change -- before the file is fully written?)

Basically I think this is just treating the symptom... but it works for me

[lihaoyi]

The mill client writes to that file 10 times a second, and the mill server reads from that file 10 times a second. The file contains 1 line with 2 numbers separated by a space.

There isn't much more to it. Really makes me wonder why that logic uses 1 full CPU core on your machine!

[BardurArantsson]

Pull request here: #4110

[BardurArantsson]

[EDIT: Whoops, not in thread]