docker / for-mac

Bug reports for Docker Desktop for Mac
https://www.docker.com/products/docker#/mac
2.43k stars 118 forks source link

com.docker.hyperkit 100% cpu usage is back again #3499

Closed stephenc closed 3 years ago

stephenc commented 5 years ago

Summary

This is an issue with a lot of comments and rumors of fixes and confusion over what the exact issue underlying this bug is.

False leads

Here is what we know, because it can get lost in the comments.

Current hypothesis

There is an edge case in the filesystem synchronization code and when triggered it causes the receiver process in the Docker VM to go into an infinite loop and suck all the CPU cycles of one CPU core.

As of 2020-05-28, the leading candidate for this hypothesis is around this line of code: https://github.com/moby/hyperkit/blob/79c6a4d95e3f8a59f774eb66e3ea333a277292c6/src/lib/mirage_block_ocaml.ml#L422 and see this comment: https://github.com/docker/for-mac/issues/3499#issuecomment-623960890

Mitigations

Things that can cause the infinite loop seem to involve syncing of file system events between OS-X and the docker VM. The fewer file system shares you have, the less likely this is to occur. Similarly, if you can switch your filesystem mounts to :cached then that means there will be fewer notifications being sent back and forth between the Docker VM and OS-X, just less chance of the issue.

The native Docker K8s implementation seems to involve a lot of this kind of sync, so you are more likely to trip over the issue.

Stuff I have found that makes life easier:

  1. Remove all unnecessary file sharing mounts. I had this issue a lot when I included the default /Volumes but once I removed that the frequency of occurrence was greatly reduced: Screenshot 2020-05-12 at 11 09 44 I leave /private and /tmp because some of the projects I work on have tests that use TempDirs as docker volume mounts.
  2. Ensure there is more than one CPU core allocated to Docker. If you have more than 1 core then you can quit docker without a reboot (NOTE: in extreme cases you may need to force quit docker processes from Activity Monitor's process window Screenshot 2020-05-12 at 11 13 15
  3. Switching to k3d in place of Docker's native K8s implementation.
  4. I recommend quitting the Docker application before suspending OS-X and at the end of your work-day. The longer the process runs for the more likely to hit the infinite loop. If you quit it daily there is less risk

Hope this helps.

P.S. Remember your actual containers that you are running may be causing their own CPU usage spikes... that is not what this bug is about... those CPU spikes are likely the result of bugs in your containers or perhaps how you have configured volume mounts causing your containers to see excessive file system changes. This bug is for Docker CPU spiking when not running any containers or pods at all

P.P.S. I have heard interesting things about using Multipass to run k3s on OS-X without docker at all: https://medium.com/@zhimin.wen/running-k3s-with-multipass-on-mac-fbd559966f7c but that would, AIUI, force me to use something like Kaniko to actually build docker images within the k3s and that gets really ugly really fast. My current recommendation is to use k3d as my usage patters of Docker with k3d is only spiking the CPU about once a week for me.


Original bug report

Expected behavior

com.docker.hyperkit should not turn my Mac into a space heater with megawatt output when stopping all running containers

Actual behavior

com.docker.hyperkit process jumps to use all available CPU resources multiple times per day, some times when only vaguely interacting with docker.

All docker commands lock up, e.g. docker ps

Information

Diagnostic logs

This seems relevant

2019-01-31 14:47:08.250611+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Discards have finished, 15975 clusters have been discarded
2019-01-31 14:47:08.283415+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: 15975 clusters are junk, 10743 moves are possible
2019-01-31 14:47:10.602322+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: resize to 377443 clusters
2019-01-31 14:47:16.712836+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: triggering background flush: 360157 used; 4494 junk; 740 erased; 1308 available; 10741 copies; 0 roots; 0 Copying; 10741 Copied; 0 Flushed; 0 Referenced; max_cluster = 377442
2019-01-31 14:47:16.722716+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: 10741 cluster copies flushed; 0 cluster copies complete; 740 clusters erased
2019-01-31 14:47:16.727609+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: flush: 360157 used; 4494 junk; 0 erased; 2048 available; 10741 copies; 0 roots; 0 Copying; 0 Copied; 10741 Flushed; 0 Referenced; max_cluster = 377442
2019-01-31 14:47:16.727780+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: need to update references to blocks
2019-01-31 14:47:16.732415+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 1 references in cluster 2
2019-01-31 14:47:16.732432+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: Dropping cache for cluster 368156
2019-01-31 14:47:16.732439+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Cluster 2 is L1: we must remap L2 references
2019-01-31 14:47:16.964145+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 4961 references in cluster 3
2019-01-31 14:47:16.991882+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 334 references in cluster 87
2019-01-31 14:47:16.994487+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 9 references in cluster 90
2019-01-31 14:47:16.994651+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 2 references in cluster 92
2019-01-31 14:47:16.994763+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 117 references in cluster 95
2019-01-31 14:47:16.995756+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 164 references in cluster 105
2019-01-31 14:47:16.996729+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 1 references in cluster 107
2019-01-31 14:47:16.996911+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 5 references in cluster 109
2019-01-31 14:47:16.997141+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 1 references in cluster 111
2019-01-31 14:47:16.997289+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 29 references in cluster 4211
2019-01-31 14:47:16.997646+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 2 references in cluster 4240
2019-01-31 14:47:16.997860+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 127 references in cluster 109307
2019-01-31 14:47:16.998964+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 6 references in cluster 110607
2019-01-31 14:47:16.999131+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 11 references in cluster 110904
2019-01-31 14:47:16.999304+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 271 references in cluster 110906
2019-01-31 14:47:17.001597+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 32 references in cluster 111201
2019-01-31 14:47:17.002278+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 159 references in cluster 112694
2019-01-31 14:47:17.003679+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 1144 references in cluster 122599
2019-01-31 14:47:17.010500+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 168 references in cluster 123535
2019-01-31 14:47:17.011438+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 18 references in cluster 123983
2019-01-31 14:47:17.011659+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 1707 references in cluster 301260
2019-01-31 14:47:17.021248+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 1472 references in cluster 302216
2019-01-31 14:47:17.029988+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: 10741 block references updated
2019-01-31 14:47:21.739205+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: triggering background flush: 360157 used; 15235 junk; 0 erased; 2048 available; 10741 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 10741 Referenced; max_cluster = 377442
2019-01-31 14:47:21.754135+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: 0 cluster copies flushed; 10741 cluster copies complete; 0 clusters erased
2019-01-31 14:47:21.758504+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: flush: 360157 used; 15235 junk; 0 erased; 2048 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 368723
2019-01-31 14:47:21.758520+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Discards (15235) over threshold (2048): waiting for discards to finish before beginning compaction
2019-01-31 14:47:26.765152+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: triggering background flush: 360157 used; 15235 junk; 0 erased; 2048 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 368723
2019-01-31 14:47:26.765175+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Discards have finished, 15235 clusters have been discarded
2019-01-31 14:47:26.765798+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: 15235 clusters are junk, 2 moves are possible
2019-01-31 14:47:26.766289+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: resize to 368724 clusters
2019-01-31 14:47:57.263519+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [ERROR] write sector = 2064 length = 4096: I/O deadline exceeded
2019-01-31 14:47:57.263532+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] ()
2019-01-31 14:47:58.284984+0000  localhost com.docker.hyperkit[83014]: [84655.248677] ata1.00: exception Emask 0x0 SAct 0x7800007f SErr 0x0 action 0x6 frozen
2019-01-31 14:47:58.286729+0000  localhost com.docker.hyperkit[83014]: [84655.250432] ata1.00: cmd 61/08:00:40:2c:80/00:00:01:00:00/40 tag 0 ncq dma 4096 out
2019-01-31 14:47:58.287798+0000  localhost com.docker.hyperkit[83014]: [84655.250432]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
2019-01-31 14:47:58.288931+0000  localhost com.docker.hyperkit[83014]: [84655.252637] ata1.00: cmd 61/08:08:f8:2e:80/00:00:01:00:00/40 tag 1 ncq dma 4096 out
2019-01-31 14:47:58.290108+0000  localhost com.docker.hyperkit[83014]: [84655.252637]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
2019-01-31 14:47:58.291471+0000  localhost com.docker.hyperkit[83014]: [84655.255038] ata1.00: cmd 61/08:10:40:64:89/00:00:01:00:00/40 tag 2 ncq dma 4096 out
2019-01-31 14:47:58.292520+0000  localhost com.docker.hyperkit[83014]: [84655.255038]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
2019-01-31 14:47:58.293670+0000  localhost com.docker.hyperkit[83014]: [84655.257371] ata1.00: cmd 61/08:18:b8:f2:89/00:00:01:00:00/40 tag 3 ncq dma 4096 out
2019-01-31 14:47:58.294738+0000  localhost com.docker.hyperkit[83014]: [84655.257371]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
2019-01-31 14:47:58.296000+0000  localhost com.docker.hyperkit[83014]: [84655.259576] ata1.00: cmd 61/08:20:18:ce:8b/00:00:01:00:00/40 tag 4 ncq dma 4096 out
2019-01-31 14:47:58.297102+0000  localhost com.docker.hyperkit[83014]: [84655.259576]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
2019-01-31 14:47:58.298233+0000  localhost com.docker.hyperkit[83014]: [84655.261941] ata1.00: cmd 61/10:28:40:08:c0/00:00:03:00:00/40 tag 5 ncq dma 8192 out
2019-01-31 14:47:58.299301+0000  localhost com.docker.hyperkit[83014]: [84655.261941]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
2019-01-31 14:47:58.300502+0000  localhost com.docker.hyperkit[83014]: [84655.264139] ata1.00: cmd 61/08:30:28:08:80/00:00:04:00:00/40 tag 6 ncq dma 4096 out
2019-01-31 14:47:58.301660+0000  localhost com.docker.hyperkit[83014]: [84655.264139]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
2019-01-31 14:47:58.303143+0000  localhost com.docker.hyperkit[83014]: [84655.266602] ata1.00: cmd 61/08:d8:10:08:00/00:00:00:00:00/40 tag 27 ncq dma 4096 out
2019-01-31 14:47:58.304193+0000  localhost com.docker.hyperkit[83014]: [84655.266602]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
2019-01-31 14:47:58.305354+0000  localhost com.docker.hyperkit[83014]: [84655.269045] ata1.00: cmd 61/10:e0:20:08:00/00:00:00:00:00/40 tag 28 ncq dma 8192 out
2019-01-31 14:47:58.306427+0000  localhost com.docker.hyperkit[83014]: [84655.269045]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
2019-01-31 14:47:58.307576+0000  localhost com.docker.hyperkit[83014]: [84655.271265] ata1.00: cmd 61/08:e8:18:08:80/00:00:01:00:00/40 tag 29 ncq dma 4096 out
2019-01-31 14:47:58.308647+0000  localhost com.docker.hyperkit[83014]: [84655.271265]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
2019-01-31 14:47:58.309876+0000  localhost com.docker.hyperkit[83014]: [84655.273485] ata1.00: cmd 61/10:f0:00:09:80/00:00:01:00:00/40 tag 30 ncq dma 8192 out
2019-01-31 14:47:58.310924+0000  localhost com.docker.hyperkit[83014]: [84655.273485]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
2019-01-31 14:47:58.311799+0000  localhost com.docker.hyperkit[83014]: [84655.275896] ata1: hard resetting link
2019-01-31 14:48:12.351756+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: triggering background flush: 360157 used; 6514 junk; 153 erased; 1895 available; 2 copies; 0 roots; 0 Copying; 2 Copied; 0 Flushed; 0 Referenced; max_cluster = 368723
2019-01-31 14:48:12.351796+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: 2 cluster copies flushed; 0 cluster copies complete; 153 clusters erased
2019-01-31 14:48:12.355540+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: flush: 360157 used; 6514 junk; 0 erased; 2048 available; 2 copies; 0 roots; 0 Copying; 0 Copied; 2 Flushed; 0 Referenced; max_cluster = 368723
2019-01-31 14:48:12.355560+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: need to update references to blocks
2019-01-31 14:48:12.355569+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 2 references in cluster 302216
2019-01-31 14:48:12.355673+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: 2 block references updated
2019-01-31 14:48:17.363777+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: triggering background flush: 360157 used; 6516 junk; 0 erased; 2048 available; 2 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 2 Referenced; max_cluster = 368723
2019-01-31 14:48:17.364232+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: 0 cluster copies flushed; 2 cluster copies complete; 0 clusters erased
2019-01-31 14:48:17.368042+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: flush: 360157 used; 6516 junk; 0 erased; 2048 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 360917
2019-01-31 14:48:17.368054+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Discards (6516) over threshold (2048): waiting for discards to finish before beginning compaction
2019-01-31 14:48:22.374180+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: triggering background flush: 360157 used; 6516 junk; 0 erased; 2048 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 360917
2019-01-31 14:48:22.374211+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] Discards have finished, 6516 clusters have been discarded
2019-01-31 14:48:22.374369+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: 6516 clusters are junk, 0 moves are possible
2019-01-31 14:48:22.374390+0000  localhost com.docker.driver.amd64-linux[83008]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: resize to 360918 clusters
2019-01-31 14:48:28.144519+0000  localhost com.docker.hyperkit[83014]: [84685.108358] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [sntpc:1432]

A second log after restarting docker from previous one. Only docker commands executed in between restart and this lock-up:

$ docker system df
TYPE                TOTAL               ACTIVE              SIZE                RECLAIMABLE
Images              369                 2                   18.3GB              18.23GB (99%)
Containers          2                   0                   119B                119B (100%)
Local Volumes       148                 2                   3.145GB             3.006GB (95%)
Build Cache         0                   0                   0B                  0B
$ docker system prune
WARNING! This will remove:
        - all stopped containers
        - all networks not used by at least one container
        - all dangling images
        - all dangling build cache
Are you sure you want to continue? [y/N] y
Deleted Containers:
40936e28cc8979872bd219393517c57985672e18d496b9a822c2c789c9304cd4
87b67542060055fc7711d502f591f723685f5392edc4901941dcfb6c414ec34f

Deleted Networks:
developer-env_default
[...snip...]

Deleted Images:
deleted: sha256:8d3ca4a665ad4910e0cb141992ad77f912013431eacc12cad2dc726adab863d3
[...snip...]
deleted: sha256:c192137e0442419bd675f5dde9897ae2c3994d7ff75506756842a722637a04b1

Total reclaimed space: 6.181GB
$ docker system df
TYPE                TOTAL               ACTIVE              SIZE                RECLAIMABLE
Images              79                  0                   12.12GB             12.12GB (100%)
Containers          0                   0                   0B                  0B
Local Volumes       148                 0                   3.145GB             3.145GB (100%)
Build Cache         0                   0                   0B                  0B

And the logs:

Timestamp                       (process)[PID]    
2019-01-31 15:12:00.357270+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: resize to 358711 clusters
2019-01-31 15:12:19.018687+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: triggering background flush: 254228 used; 85553 junk; 7 erased; 2041 available; 16879 copies; 0 roots; 0 Copying; 16879 Copied; 0 Flushed; 0 Referenced; max_cluster = 358710
2019-01-31 15:12:19.033440+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: 16879 cluster copies flushed; 0 cluster copies complete; 7 clusters erased
2019-01-31 15:12:19.037595+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: flush: 254228 used; 85553 junk; 0 erased; 2048 available; 16879 copies; 0 roots; 0 Copying; 0 Copied; 16879 Flushed; 0 Referenced; max_cluster = 358710
2019-01-31 15:12:19.037945+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: need to update references to blocks
2019-01-31 15:12:19.043450+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 5 references in cluster 2
2019-01-31 15:12:19.043467+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: Dropping cache for cluster 339635
2019-01-31 15:12:19.043475+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: Dropping cache for cluster 322529
2019-01-31 15:12:19.043481+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: Dropping cache for cluster 302216
2019-01-31 15:12:19.043487+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: Dropping cache for cluster 301260
2019-01-31 15:12:19.043493+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: Dropping cache for cluster 277152
2019-01-31 15:12:19.043500+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Cluster 2 is L1: we must remap L2 references
2019-01-31 15:12:19.170059+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 1 references in cluster 3
2019-01-31 15:12:19.170129+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 13 references in cluster 90
2019-01-31 15:12:19.170313+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 11 references in cluster 95
2019-01-31 15:12:19.170497+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 3241 references in cluster 99
2019-01-31 15:12:19.183546+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 375 references in cluster 101
2019-01-31 15:12:19.185108+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 784 references in cluster 105
2019-01-31 15:12:19.188340+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 355 references in cluster 111
2019-01-31 15:12:19.189763+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 473 references in cluster 113
2019-01-31 15:12:19.191759+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 1350 references in cluster 4211
2019-01-31 15:12:19.197097+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 1790 references in cluster 4214
2019-01-31 15:12:19.203773+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 3414 references in cluster 4216
2019-01-31 15:12:19.215698+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 769 references in cluster 4218
2019-01-31 15:12:19.219065+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 1 references in cluster 41742
2019-01-31 15:12:19.219252+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 4134 references in cluster 78405
2019-01-31 15:12:19.237168+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 128 references in cluster 110906
2019-01-31 15:12:19.237937+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 1 references in cluster 124070
2019-01-31 15:12:19.238064+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 32 references in cluster 240803
2019-01-31 15:12:19.238624+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 2 references in cluster 13176
2019-01-31 15:12:19.238821+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: 16879 block references updated
2019-01-31 15:12:24.044672+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: triggering background flush: 254228 used; 102432 junk; 0 erased; 2048 available; 16879 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 16879 Referenced; max_cluster = 358710
2019-01-31 15:12:24.062490+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: 0 cluster copies flushed; 16879 cluster copies complete; 0 clusters erased
2019-01-31 15:12:24.066273+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: flush: 254228 used; 102432 junk; 0 erased; 2048 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 302028
2019-01-31 15:12:24.066307+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Discards (102432) over threshold (2048): waiting for discards to finish before beginning compaction
2019-01-31 15:12:29.071976+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: triggering background flush: 254228 used; 102432 junk; 0 erased; 2048 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 302028
2019-01-31 15:12:29.072001+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Discards have finished, 102432 clusters have been discarded
2019-01-31 15:12:29.075070+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: 102432 clusters are junk, 2 moves are possible
2019-01-31 15:12:29.075503+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: resize to 302029 clusters
2019-01-31 15:13:08.657787+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [ERROR] write sector = 117988448 length = 4096: I/O deadline exceeded
2019-01-31 15:13:08.657802+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] ()
2019-01-31 15:13:09.134968+0000  localhost com.docker.hyperkit[74256]: [ 1056.051160] ata1.00: exception Emask 0x0 SAct 0x30 SErr 0x0 action 0x6 frozen
2019-01-31 15:13:09.136017+0000  localhost com.docker.hyperkit[74256]: [ 1056.052161] ata1.00: cmd 61/08:20:60:5c:08/00:00:07:00:00/40 tag 4 ncq dma 4096 out
2019-01-31 15:13:09.136979+0000  localhost com.docker.hyperkit[74256]: [ 1056.052161]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
2019-01-31 15:13:09.138007+0000  localhost com.docker.hyperkit[74256]: [ 1056.054170] ata1.00: cmd 61/10:28:18:b5:86/00:00:03:00:00/40 tag 5 ncq dma 8192 out
2019-01-31 15:13:09.138972+0000  localhost com.docker.hyperkit[74256]: [ 1056.054170]          res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
2019-01-31 15:13:09.139483+0000  localhost com.docker.hyperkit[74256]: [ 1056.056168] ata1: hard resetting link
2019-01-31 15:14:00.768764+0000  localhost com.docker.hyperkit[74256]: [ 1107.684976] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [sntpc:1417]
2019-01-31 15:14:00.769472+0000  localhost com.docker.hyperkit[74256]: [ 1107.685953] Modules linked in: xfrm_user xfrm_algo
2019-01-31 15:14:00.770385+0000  localhost com.docker.hyperkit[74256]: [ 1107.686662] CPU: 0 PID: 1417 Comm: sntpc Not tainted 4.9.125-linuxkit #1
2019-01-31 15:14:00.771088+0000  localhost com.docker.hyperkit[74256]: [ 1107.687574] Hardware name:  BHYVE, BIOS 1.00 03/14/2014
2019-01-31 15:14:00.771879+0000  localhost com.docker.hyperkit[74256]: [ 1107.688276] task: ffff96c969603000 task.stack: ffffb90d019d8000
2019-01-31 15:14:00.773101+0000  localhost com.docker.hyperkit[74256]: [ 1107.689067] RIP: 0010:[<ffffffff9b13c208>]  [<ffffffff9b13c208>] smp_call_function_many+0x1f1/0x204
2019-01-31 15:14:00.773814+0000  localhost com.docker.hyperkit[74256]: [ 1107.690289] RSP: 0018:ffffb90d019dbdf8  EFLAGS: 00000202
2019-01-31 15:14:00.774766+0000  localhost com.docker.hyperkit[74256]: [ 1107.691002] RAX: 0000000000000001 RBX: ffff96c97fc1a008 RCX: 0000000000000001
2019-01-31 15:14:00.775728+0000  localhost com.docker.hyperkit[74256]: [ 1107.691954] RDX: ffff96c97fc9c918 RSI: 0000000000000000 RDI: ffff96c97fc1a008
2019-01-31 15:14:00.776676+0000  localhost com.docker.hyperkit[74256]: [ 1107.692916] RBP: ffff96c97fc1a000 R08: ffffffffffffffff R09: 000000000000000e
2019-01-31 15:14:00.777627+0000  localhost com.docker.hyperkit[74256]: [ 1107.693864] R10: ffffb90d019dbdf8 R11: 0000000000000000 R12: 0000000000000001
2019-01-31 15:14:00.778578+0000  localhost com.docker.hyperkit[74256]: [ 1107.694815] R13: 0000000000019fc0 R14: 0000000000000000 R15: ffffffff9ba433e0
2019-01-31 15:14:00.779657+0000  localhost com.docker.hyperkit[74256]: [ 1107.695766] FS:  00007f7da32dcb88(0000) GS:ffff96c97fc00000(0000) knlGS:0000000000000000
2019-01-31 15:14:00.780425+0000  localhost com.docker.hyperkit[74256]: [ 1107.696845] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
2019-01-31 15:14:00.781393+0000  localhost com.docker.hyperkit[74256]: [ 1107.697613] CR2: 000000c420177010 CR3: 0000000306a24000 CR4: 0000000000060630
2019-01-31 15:14:00.781679+0000  localhost com.docker.hyperkit[74256]: [ 1107.698582] Stack:
2019-01-31 15:14:00.782745+0000  localhost com.docker.hyperkit[74256]: [ 1107.698868]  ffffffff9b12bd86 00000003017e75f0 ffffffff9b12bd86 0000000000000000
2019-01-31 15:14:00.783809+0000  localhost com.docker.hyperkit[74256]: [ 1107.699933]  0000000000000202 0000000000000000 0000000000000000 0000000000000000
2019-01-31 15:14:00.784872+0000  localhost com.docker.hyperkit[74256]: [ 1107.700996]  ffffffff9b13c239 ffffffff9b13c252 ffffb90d019dbef8 ffffb90d019dbe98
2019-01-31 15:14:00.785212+0000  localhost com.docker.hyperkit[74256]: [ 1107.702060] Call Trace:
2019-01-31 15:14:00.786072+0000  localhost com.docker.hyperkit[74256]: [ 1107.702402]  [<ffffffff9b12bd86>] ? __hrtimer_get_remaining+0x6d/0x6d
2019-01-31 15:14:00.786931+0000  localhost com.docker.hyperkit[74256]: [ 1107.703261]  [<ffffffff9b12bd86>] ? __hrtimer_get_remaining+0x6d/0x6d
2019-01-31 15:14:00.787723+0000  localhost com.docker.hyperkit[74256]: [ 1107.704120]  [<ffffffff9b13c239>] ? smp_call_function+0x1e/0x21
2019-01-31 15:14:00.788446+0000  localhost com.docker.hyperkit[74256]: [ 1107.704911]  [<ffffffff9b13c252>] ? on_each_cpu+0x16/0x40
2019-01-31 15:14:00.789191+0000  localhost com.docker.hyperkit[74256]: [ 1107.705634]  [<ffffffff9b12c392>] ? clock_was_set+0x18/0x1d
2019-01-31 15:14:00.789984+0000  localhost com.docker.hyperkit[74256]: [ 1107.706381]  [<ffffffff9b130d3a>] ? do_settimeofday64+0xe6/0xf2
2019-01-31 15:14:00.790824+0000  localhost com.docker.hyperkit[74256]: [ 1107.707173]  [<ffffffff9b1294f6>] ? do_sys_settimeofday64+0x98/0xf1
2019-01-31 15:14:00.791613+0000  localhost com.docker.hyperkit[74256]: [ 1107.708022]  [<ffffffff9b129607>] ? SyS_settimeofday+0xb8/0xda
2019-01-31 15:14:00.792386+0000  localhost com.docker.hyperkit[74256]: [ 1107.708806]  [<ffffffff9b0033f4>] ? do_syscall_64+0x6f/0x7f
2019-01-31 15:14:00.793317+0000  localhost com.docker.hyperkit[74256]: [ 1107.709577]  [<ffffffff9b7e74ce>] ? entry_SYSCALL_64_after_swapgs+0x58/0xc6
2019-01-31 15:14:00.797134+0000  localhost com.docker.hyperkit[74256]: [ 1107.710505] Code: 48 89 de 89 c7 e8 12 f9 ff ff 3b 05 77 96 c0 00 7d 1d 48 63 c8 48 8b 55 00 48 03 14 cd e0 33 a4 9b 8b 4a 18 80 e1 01 74 04 f3 90 <eb> f4 eb d1 48 83 c4 10 5b 5d 41 5c 41 5d 41 5e 41 5f c3 0f 1f
2019-01-31 15:14:09.170792+0000  localhost com.docker.hyperkit[74256]: [ 1116.087082] INFO: rcu_sched detected stalls on CPUs/tasks:
2019-01-31 15:14:09.172088+0000  localhost com.docker.hyperkit[74256]: [ 1116.087985]   1-...: (1 GPs behind) idle=b17/140000000000000/0 softirq=11952/11952 fqs=2992
2019-01-31 15:14:09.173073+0000  localhost com.docker.hyperkit[74256]: [ 1116.089278]   (detected by 0, t=6002 jiffies, g=2946, c=2945, q=14)
2019-01-31 15:14:09.173590+0000  localhost com.docker.hyperkit[74256]: [ 1116.090264] Task dump for CPU 1:
2019-01-31 15:14:09.174738+0000  localhost com.docker.hyperkit[74256]: [ 1116.090781] scsi_eh_0       R  running task        0   267      2 0x00000008
2019-01-31 15:14:09.175987+0000  localhost com.docker.hyperkit[74256]: [ 1116.091930]  0000000000000000 ffffffff9b55fc51 0000000000000000 ffff96c96f2dc000
2019-01-31 15:14:09.177229+0000  localhost com.docker.hyperkit[74256]: [ 1116.093177]  ffffb90d0086be00 ffff96c96f36c000 ffffb90d0086be78 ffff96c96f698580
2019-01-31 15:14:09.178473+0000  localhost com.docker.hyperkit[74256]: [ 1116.094419]  0000000000000246 ffffffff9b56001f ffff96c96dec3618 ffff96c96dc40098
2019-01-31 15:14:09.178872+0000  localhost com.docker.hyperkit[74256]: [ 1116.095663] Call Trace:
2019-01-31 15:14:09.179983+0000  localhost com.docker.hyperkit[74256]: [ 1116.096068]  [<ffffffff9b55fc51>] ? ata_scsi_port_error_handler+0x231/0x55c
2019-01-31 15:14:09.180942+0000  localhost com.docker.hyperkit[74256]: [ 1116.097182]  [<ffffffff9b56001f>] ? ata_scsi_error+0xa3/0xdb
2019-01-31 15:14:09.181964+0000  localhost com.docker.hyperkit[74256]: [ 1116.098143]  [<ffffffff9b52f356>] ? scsi_error_handler+0xb2/0x478
2019-01-31 15:14:09.182969+0000  localhost com.docker.hyperkit[74256]: [ 1116.099175]  [<ffffffff9b100ab9>] ? finish_task_switch+0x115/0x194
2019-01-31 15:14:09.183832+0000  localhost com.docker.hyperkit[74256]: [ 1116.100164]  [<ffffffff9b7e4913>] ? __schedule+0x36c/0x470
2019-01-31 15:14:09.184763+0000  localhost com.docker.hyperkit[74256]: [ 1116.101025]  [<ffffffff9b52f2a4>] ? scsi_eh_get_sense+0xdd/0xdd
2019-01-31 15:14:09.185561+0000  localhost com.docker.hyperkit[74256]: [ 1116.101955]  [<ffffffff9b0f9f9a>] ? kthread+0xb6/0xbe
2019-01-31 15:14:09.186459+0000  localhost com.docker.hyperkit[74256]: [ 1116.102753]  [<ffffffff9b7e75f0>] ? __switch_to_asm+0x40/0x70
2019-01-31 15:14:09.187356+0000  localhost com.docker.hyperkit[74256]: [ 1116.103651]  [<ffffffff9b0f9ee4>] ? init_completion+0x1d/0x1d
2019-01-31 15:14:09.188228+0000  localhost com.docker.hyperkit[74256]: [ 1116.104548]  [<ffffffff9b7e7677>] ? ret_from_fork+0x57/0x70
2019-01-31 15:14:36.741096+0000  localhost com.docker.hyperkit[74256]: [ 1143.657309] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [sntpc:1417]
2019-01-31 15:14:36.741805+0000  localhost com.docker.hyperkit[74256]: [ 1143.658285] Modules linked in: xfrm_user xfrm_algo
2019-01-31 15:14:36.742854+0000  localhost com.docker.hyperkit[74256]: [ 1143.658994] CPU: 0 PID: 1417 Comm: sntpc Tainted: G             L  4.9.125-linuxkit #1
2019-01-31 15:14:36.743554+0000  localhost com.docker.hyperkit[74256]: [ 1143.660042] Hardware name:  BHYVE, BIOS 1.00 03/14/2014
2019-01-31 15:14:36.744351+0000  localhost com.docker.hyperkit[74256]: [ 1143.660743] task: ffff96c969603000 task.stack: ffffb90d019d8000
2019-01-31 15:14:36.745699+0000  localhost com.docker.hyperkit[74256]: [ 1143.661540] RIP: 0010:[<ffffffff9b13c208>]  [<ffffffff9b13c208>] smp_call_function_many+0x1f1/0x204
2019-01-31 15:14:36.746484+0000  localhost com.docker.hyperkit[74256]: [ 1143.662894] RSP: 0018:ffffb90d019dbdf8  EFLAGS: 00000202
2019-01-31 15:14:36.747595+0000  localhost com.docker.hyperkit[74256]: [ 1143.663677] RAX: 0000000000000001 RBX: ffff96c97fc1a008 RCX: 0000000000000001
2019-01-31 15:14:36.748567+0000  localhost com.docker.hyperkit[74256]: [ 1143.664794] RDX: ffff96c97fc9c918 RSI: 0000000000000000 RDI: ffff96c97fc1a008
2019-01-31 15:14:36.749529+0000  localhost com.docker.hyperkit[74256]: [ 1143.665756] RBP: ffff96c97fc1a000 R08: ffffffffffffffff R09: 000000000000000e
2019-01-31 15:14:36.750497+0000  localhost com.docker.hyperkit[74256]: [ 1143.666718] R10: ffffb90d019dbdf8 R11: 0000000000000000 R12: 0000000000000001
2019-01-31 15:14:36.751452+0000  localhost com.docker.hyperkit[74256]: [ 1143.667687] R13: 0000000000019fc0 R14: 0000000000000000 R15: ffffffff9ba433e0
2019-01-31 15:14:36.752538+0000  localhost com.docker.hyperkit[74256]: [ 1143.668654] FS:  00007f7da32dcb88(0000) GS:ffff96c97fc00000(0000) knlGS:0000000000000000
2019-01-31 15:14:36.753311+0000  localhost com.docker.hyperkit[74256]: [ 1143.669730] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
2019-01-31 15:14:36.754257+0000  localhost com.docker.hyperkit[74256]: [ 1143.670499] CR2: 000000c420177010 CR3: 0000000306a24000 CR4: 0000000000060630
2019-01-31 15:14:36.754542+0000  localhost com.docker.hyperkit[74256]: [ 1143.671446] Stack:
2019-01-31 15:14:36.755610+0000  localhost com.docker.hyperkit[74256]: [ 1143.671731]  ffffffff9b12bd86 00000003017e75f0 ffffffff9b12bd86 0000000000000000
2019-01-31 15:14:36.756677+0000  localhost com.docker.hyperkit[74256]: [ 1143.672797]  0000000000000202 0000000000000000 0000000000000000 0000000000000000
2019-01-31 15:14:36.757748+0000  localhost com.docker.hyperkit[74256]: [ 1143.673865]  ffffffff9b13c239 ffffffff9b13c252 ffffb90d019dbef8 ffffb90d019dbe98
2019-01-31 15:14:36.758089+0000  localhost com.docker.hyperkit[74256]: [ 1143.674935] Call Trace:
2019-01-31 15:14:36.758956+0000  localhost com.docker.hyperkit[74256]: [ 1143.675281]  [<ffffffff9b12bd86>] ? __hrtimer_get_remaining+0x6d/0x6d
2019-01-31 15:14:36.759815+0000  localhost com.docker.hyperkit[74256]: [ 1143.676146]  [<ffffffff9b12bd86>] ? __hrtimer_get_remaining+0x6d/0x6d
2019-01-31 15:14:36.760606+0000  localhost com.docker.hyperkit[74256]: [ 1143.677004]  [<ffffffff9b13c239>] ? smp_call_function+0x1e/0x21
2019-01-31 15:14:36.761338+0000  localhost com.docker.hyperkit[74256]: [ 1143.677795]  [<ffffffff9b13c252>] ? on_each_cpu+0x16/0x40
2019-01-31 15:14:36.762085+0000  localhost com.docker.hyperkit[74256]: [ 1143.678528]  [<ffffffff9b12c392>] ? clock_was_set+0x18/0x1d
2019-01-31 15:14:36.762876+0000  localhost com.docker.hyperkit[74256]: [ 1143.679274]  [<ffffffff9b130d3a>] ? do_settimeofday64+0xe6/0xf2
2019-01-31 15:14:36.763713+0000  localhost com.docker.hyperkit[74256]: [ 1143.680066]  [<ffffffff9b1294f6>] ? do_sys_settimeofday64+0x98/0xf1
2019-01-31 15:14:36.764494+0000  localhost com.docker.hyperkit[74256]: [ 1143.680902]  [<ffffffff9b129607>] ? SyS_settimeofday+0xb8/0xda
2019-01-31 15:14:36.765240+0000  localhost com.docker.hyperkit[74256]: [ 1143.681682]  [<ffffffff9b0033f4>] ? do_syscall_64+0x6f/0x7f
2019-01-31 15:14:36.766169+0000  localhost com.docker.hyperkit[74256]: [ 1143.682430]  [<ffffffff9b7e74ce>] ? entry_SYSCALL_64_after_swapgs+0x58/0xc6
2019-01-31 15:14:36.770010+0000  localhost com.docker.hyperkit[74256]: [ 1143.683357] Code: 48 89 de 89 c7 e8 12 f9 ff ff 3b 05 77 96 c0 00 7d 1d 48 63 c8 48 8b 55 00 48 03 14 cd e0 33 a4 9b 8b 4a 18 80 e1 01 74 04 f3 90 <eb> f4 eb d1 48 83 c4 10 5b 5d 41 5c 41 5d 41 5e 41 5f c3 0f 1f
2019-01-31 15:14:40.028247+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Discards (45750) over threshold (2048): waiting for discards to finish before beginning compaction
2019-01-31 15:14:44.971259+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: triggering background flush: 254228 used; 45750 junk; 1368 erased; 680 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 302028
2019-01-31 15:14:44.971294+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: 0 cluster copies flushed; 0 cluster copies complete; 1368 clusters erased
2019-01-31 15:14:44.974849+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: flush: 254228 used; 45750 junk; 0 erased; 2048 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 302028
2019-01-31 15:14:45.030025+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Discards have finished, 45750 clusters have been discarded
2019-01-31 15:14:45.031205+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: 45750 clusters are junk, 2 moves are possible
2019-01-31 15:14:45.031709+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: resize to 302029 clusters
2019-01-31 15:14:49.982256+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: triggering background flush: 254228 used; 45748 junk; 0 erased; 2048 available; 2 copies; 0 roots; 0 Copying; 2 Copied; 0 Flushed; 0 Referenced; max_cluster = 302028
2019-01-31 15:14:49.982281+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: 2 cluster copies flushed; 0 cluster copies complete; 0 clusters erased
2019-01-31 15:14:49.985425+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: flush: 254228 used; 45748 junk; 0 erased; 2048 available; 2 copies; 0 roots; 0 Copying; 0 Copied; 2 Flushed; 0 Referenced; max_cluster = 302028
2019-01-31 15:14:49.985436+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: need to update references to blocks
2019-01-31 15:14:49.985447+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 1 references in cluster 4240
2019-01-31 15:14:49.985685+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Updating 1 references in cluster 13246
2019-01-31 15:14:49.985768+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: 2 block references updated
2019-01-31 15:14:54.311895+0000  localhost launchservicesd[94]: (LaunchServices) [com.apple.launchservices:cas] Moving App:"Docker" asn:0x0-8fc8fc pid:74212 refs=8 @ 0x7fb1f0a2b040 to front of visible list.
2019-01-31 15:14:54.312029+0000  localhost launchservicesd[94]: (LaunchServices) [com.apple.launchservices:cas] Making App:"Docker" asn:0x0-8fc8fc pid:74212 refs=8 @ 0x7fb1f0a2b040 into menu bar owning process, oldOwner=App:"Terminal" asn:0x0-425425 pid:34206 refs=7 @ 0x7fb1eee174e0
2019-01-31 15:14:54.312036+0000  localhost launchservicesd[94]: (LaunchServices) [com.apple.launchservices:cas] POLICY: Setting application App:"Docker" asn:0x0-8fc8fc pid:74212 refs=9 @ 0x7fb1f0a2b040, pid=74212 to PRIO_DARWIN_ROLE_UI_FOCAL
2019-01-31 15:14:54.319587+0000  localhost Docker[74212]: (LaunchServices) [com.apple.launchservices:cas] Removing cached information for app [ 0x0/0x425425]  "Terminal", as its seed is different from that in shared memory ( 1266 vs 1268)
2019-01-31 15:14:54.988855+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: triggering background flush: 254228 used; 45750 junk; 0 erased; 2048 available; 2 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 2 Referenced; max_cluster = 302028
2019-01-31 15:14:54.989357+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: 0 cluster copies flushed; 2 cluster copies complete; 0 clusters erased
2019-01-31 15:14:54.992541+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: flush: 254228 used; 45750 junk; 0 erased; 2048 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 254299
2019-01-31 15:14:54.992555+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Discards (45750) over threshold (2048): waiting for discards to finish before beginning compaction
2019-01-31 15:14:56.353116+0000  localhost launchservicesd[94]: (LaunchServices) [com.apple.launchservices:cas] Making App:"Google Chrome" asn:0x0-413413 pid:2824 refs=8 @ 0x7fb1eef29d50 into menu bar owning process, oldOwner=App:"Docker" asn:0x0-8fc8fc pid:74212 refs=7 @ 0x7fb1f0a2b040
2019-01-31 15:14:56.353807+0000  localhost launchservicesd[94]: (LaunchServices) [com.apple.launchservices:cas] POLICY: Setting application App:"Docker" asn:0x0-8fc8fc pid:74212 refs=6 @ 0x7fb1f0a2b040, pid=74212 to PRIO_DARWIN_ROLE_UI_NON_FOCAL
2019-01-31 15:14:56.356357+0000  localhost Docker[74212]: (LaunchServices) 27366555: RECEIVED OUT-OF-SEQUENCE NOTIFICATION: 0 vs 9203, 513, <private>
2019-01-31 15:15:00.000622+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: triggering background flush: 254228 used; 45750 junk; 0 erased; 2048 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 254299
2019-01-31 15:15:00.000645+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] Discards have finished, 45750 clusters have been discarded
2019-01-31 15:15:00.001765+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: 45750 clusters are junk, 0 moves are possible
2019-01-31 15:15:00.001774+0000  localhost com.docker.driver.amd64-linux[74250]: hyperkit: stderr: com.docker.hyperkit: [INFO] block recycler: resize to 254300 clusters
2019-01-31 15:15:04.720689+0000  localhost com.docker.hyperkit[74256]: [ 1171.636898] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [sntpc:1417]
2019-01-31 15:15:04.721403+0000  localhost com.docker.hyperkit[74256]: [ 1171.637878] Modules linked in: xfrm_user xfrm_algo
2019-01-31 15:15:04.722460+0000  localhost com.docker.hyperkit[74256]: [ 1171.638592] CPU: 0 PID: 1417 Comm: sntpc Tainted: G             L  4.9.125-linuxkit #1
2019-01-31 15:15:04.723164+0000  localhost com.docker.hyperkit[74256]: [ 1171.639648] Hardware name:  BHYVE, BIOS 1.00 03/14/2014
2019-01-31 15:15:04.723959+0000  localhost com.docker.hyperkit[74256]: [ 1171.640352] task: ffff96c969603000 task.stack: ffffb90d019d8000
2019-01-31 15:15:04.725184+0000  localhost com.docker.hyperkit[74256]: [ 1171.641147] RIP: 0010:[<ffffffff9b13c208>]  [<ffffffff9b13c208>] smp_call_function_many+0x1f1/0x204
2019-01-31 15:15:04.725900+0000  localhost com.docker.hyperkit[74256]: [ 1171.642373] RSP: 0018:ffffb90d019dbdf8  EFLAGS: 00000202
2019-01-31 15:15:04.726853+0000  localhost com.docker.hyperkit[74256]: [ 1171.643088] RAX: 0000000000000001 RBX: ffff96c97fc1a008 RCX: 0000000000000001
2019-01-31 15:15:04.727806+0000  localhost com.docker.hyperkit[74256]: [ 1171.644041] RDX: ffff96c97fc9c918 RSI: 0000000000000000 RDI: ffff96c97fc1a008
2019-01-31 15:15:04.728758+0000  localhost com.docker.hyperkit[74256]: [ 1171.644993] RBP: ffff96c97fc1a000 R08: ffffffffffffffff R09: 000000000000000e
2019-01-31 15:15:04.729713+0000  localhost com.docker.hyperkit[74256]: [ 1171.645946] R10: ffffb90d019dbdf8 R11: 0000000000000000 R12: 0000000000000001
2019-01-31 15:15:04.730665+0000  localhost com.docker.hyperkit[74256]: [ 1171.646900] R13: 0000000000019fc0 R14: 0000000000000000 R15: ffffffff9ba433e0
2019-01-31 15:15:04.731745+0000  localhost com.docker.hyperkit[74256]: [ 1171.647854] FS:  00007f7da32dcb88(0000) GS:ffff96c97fc00000(0000) knlGS:0000000000000000
2019-01-31 15:15:04.732517+0000  localhost com.docker.hyperkit[74256]: [ 1171.648933] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
2019-01-31 15:15:04.733491+0000  localhost com.docker.hyperkit[74256]: [ 1171.649705] CR2: 000000c420177010 CR3: 0000000306a24000 CR4: 0000000000060630
2019-01-31 15:15:04.733779+0000  localhost com.docker.hyperkit[74256]: [ 1171.650680] Stack:
2019-01-31 15:15:04.734873+0000  localhost com.docker.hyperkit[74256]: [ 1171.650975]  ffffffff9b12bd86 00000003017e75f0 ffffffff9b12bd86 0000000000000000
2019-01-31 15:15:04.735961+0000  localhost com.docker.hyperkit[74256]: [ 1171.652065]  0000000000000202 0000000000000000 0000000000000000 0000000000000000
2019-01-31 15:15:04.737040+0000  localhost com.docker.hyperkit[74256]: [ 1171.653150]  ffffffff9b13c239 ffffffff9b13c252 ffffb90d019dbef8 ffffb90d019dbe98
2019-01-31 15:15:04.737387+0000  localhost com.docker.hyperkit[74256]: [ 1171.654228] Call Trace:
2019-01-31 15:15:04.738260+0000  localhost com.docker.hyperkit[74256]: [ 1171.654579]  [<ffffffff9b12bd86>] ? __hrtimer_get_remaining+0x6d/0x6d
2019-01-31 15:15:04.739135+0000  localhost com.docker.hyperkit[74256]: [ 1171.655451]  [<ffffffff9b12bd86>] ? __hrtimer_get_remaining+0x6d/0x6d
2019-01-31 15:15:04.739937+0000  localhost com.docker.hyperkit[74256]: [ 1171.656325]  [<ffffffff9b13c239>] ? smp_call_function+0x1e/0x21
2019-01-31 15:15:04.740669+0000  localhost com.docker.hyperkit[74256]: [ 1171.657127]  [<ffffffff9b13c252>] ? on_each_cpu+0x16/0x40
2019-01-31 15:15:04.741426+0000  localhost com.docker.hyperkit[74256]: [ 1171.657859]  [<ffffffff9b12c392>] ? clock_was_set+0x18/0x1d
2019-01-31 15:15:04.742234+0000  localhost com.docker.hyperkit[74256]: [ 1171.658616]  [<ffffffff9b130d3a>] ? do_settimeofday64+0xe6/0xf2
2019-01-31 15:15:04.743099+0000  localhost com.docker.hyperkit[74256]: [ 1171.659424]  [<ffffffff9b1294f6>] ? do_sys_settimeofday64+0x98/0xf1
2019-01-31 15:15:04.743908+0000  localhost com.docker.hyperkit[74256]: [ 1171.660290]  [<ffffffff9b129607>] ? SyS_settimeofday+0xb8/0xda
2019-01-31 15:15:04.744694+0000  localhost com.docker.hyperkit[74256]: [ 1171.661100]  [<ffffffff9b0033f4>] ? do_syscall_64+0x6f/0x7f
2019-01-31 15:15:04.745688+0000  localhost com.docker.hyperkit[74256]: [ 1171.661888]  [<ffffffff9b7e74ce>] ? entry_SYSCALL_64_after_swapgs+0x58/0xc6
2019-01-31 15:15:04.749579+0000  localhost com.docker.hyperkit[74256]: [ 1171.662880] Code: 48 89 de 89 c7 e8 12 f9 ff ff 3b 05 77 96 c0 00 7d 1d 48 63 c8 48 8b 55 00 48 03 14 cd e0 33 a4 9b 8b 4a 18 80 e1 01 74 04 f3 90 <eb> f4 eb d1 48 83 c4 10 5b 5d 41 5c 41 5d 41 5e 41 5f c3 0f 1f
2019-01-31 15:15:32.700584+0000  localhost com.docker.hyperkit[74256]: [ 1199.616795] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [sntpc:1417]
2019-01-31 15:15:32.701296+0000  localhost com.docker.hyperkit[74256]: [ 1199.617773] Modules linked in: xfrm_user xfrm_algo
2019-01-31 15:15:32.702352+0000  localhost com.docker.hyperkit[74256]: [ 1199.618486] CPU: 0 PID: 1417 Comm: sntpc Tainted: G             L  4.9.125-linuxkit #1
2019-01-31 15:15:32.703063+0000  localhost com.docker.hyperkit[74256]: [ 1199.619540] Hardware name:  BHYVE, BIOS 1.00 03/14/2014
2019-01-31 15:15:32.703859+0000  localhost com.docker.hyperkit[74256]: [ 1199.620252] task: ffff96c969603000 task.stack: ffffb90d019d8000
2019-01-31 15:15:32.705091+0000  localhost com.docker.hyperkit[74256]: [ 1199.621047] RIP: 0010:[<ffffffff9b13c208>]  [<ffffffff9b13c208>] smp_call_function_many+0x1f1/0x204
2019-01-31 15:15:32.705807+0000  localhost com.docker.hyperkit[74256]: [ 1199.622279] RSP: 0018:ffffb90d019dbdf8  EFLAGS: 00000202
2019-01-31 15:15:32.706760+0000  localhost com.docker.hyperkit[74256]: [ 1199.622995] RAX: 0000000000000001 RBX: ffff96c97fc1a008 RCX: 0000000000000001
2019-01-31 15:15:32.707713+0000  localhost com.docker.hyperkit[74256]: [ 1199.623948] RDX: ffff96c97fc9c918 RSI: 0000000000000000 RDI: ffff96c97fc1a008
2019-01-31 15:15:32.708668+0000  localhost com.docker.hyperkit[74256]: [ 1199.624901] RBP: ffff96c97fc1a000 R08: ffffffffffffffff R09: 000000000000000e
2019-01-31 15:15:32.709621+0000  localhost com.docker.hyperkit[74256]: [ 1199.625856] R10: ffffb90d019dbdf8 R11: 0000000000000000 R12: 0000000000000001
2019-01-31 15:15:32.710574+0000  localhost com.docker.hyperkit[74256]: [ 1199.626809] R13: 0000000000019fc0 R14: 0000000000000000 R15: ffffffff9ba433e0
2019-01-31 15:15:32.711653+0000  localhost com.docker.hyperkit[74256]: [ 1199.627763] FS:  00007f7da32dcb88(0000) GS:ffff96c97fc00000(0000) knlGS:0000000000000000
2019-01-31 15:15:32.712432+0000  localhost com.docker.hyperkit[74256]: [ 1199.628841] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
2019-01-31 15:15:32.713388+0000  localhost com.docker.hyperkit[74256]: [ 1199.629620] CR2: 000000c420177010 CR3: 0000000306a24000 CR4: 0000000000060630
2019-01-31 15:15:32.713674+0000  localhost com.docker.hyperkit[74256]: [ 1199.630576] Stack:
2019-01-31 15:15:32.714745+0000  localhost com.docker.hyperkit[74256]: [ 1199.630863]  ffffffff9b12bd86 00000003017e75f0 ffffffff9b12bd86 0000000000000000
2019-01-31 15:15:32.715823+0000  localhost com.docker.hyperkit[74256]: [ 1199.631933]  0000000000000202 0000000000000000 0000000000000000 0000000000000000
2019-01-31 15:15:32.716893+0000  localhost com.docker.hyperkit[74256]: [ 1199.633011]  ffffffff9b13c239 ffffffff9b13c252 ffffb90d019dbef8 ffffb90d019dbe98
2019-01-31 15:15:32.717235+0000  localhost com.docker.hyperkit[74256]: [ 1199.634081] Call Trace:
2019-01-31 15:15:32.718109+0000  localhost com.docker.hyperkit[74256]: [ 1199.634433]  [<ffffffff9b12bd86>] ? __hrtimer_get_remaining+0x6d/0x6d
2019-01-31 15:15:32.718978+0000  localhost com.docker.hyperkit[74256]: [ 1199.635301]  [<ffffffff9b12bd86>] ? __hrtimer_get_remaining+0x6d/0x6d
2019-01-31 15:15:32.719774+0000  localhost com.docker.hyperkit[74256]: [ 1199.636168]  [<ffffffff9b13c239>] ? smp_call_function+0x1e/0x21
2019-01-31 15:15:32.720502+0000  localhost com.docker.hyperkit[74256]: [ 1199.636963]  [<ffffffff9b13c252>] ? on_each_cpu+0x16/0x40
2019-01-31 15:15:32.721253+0000  localhost com.docker.hyperkit[74256]: [ 1199.637691]  [<ffffffff9b12c392>] ? clock_was_set+0x18/0x1d
2019-01-31 15:15:32.722049+0000  localhost com.docker.hyperkit[74256]: [ 1199.638442]  [<ffffffff9b130d3a>] ? do_settimeofday64+0xe6/0xf2
2019-01-31 15:15:32.722889+0000  localhost com.docker.hyperkit[74256]: [ 1199.639238]  [<ffffffff9b1294f6>] ? do_sys_settimeofday64+0x98/0xf1
2019-01-31 15:15:32.723676+0000  localhost com.docker.hyperkit[74256]: [ 1199.640079]  [<ffffffff9b129607>] ? SyS_settimeofday+0xb8/0xda
2019-01-31 15:15:32.724426+0000  localhost com.docker.hyperkit[74256]: [ 1199.640865]  [<ffffffff9b0033f4>] ? do_syscall_64+0x6f/0x7f
2019-01-31 15:15:32.725360+0000  localhost com.docker.hyperkit[74256]: [ 1199.641617]  [<ffffffff9b7e74ce>] ? entry_SYSCALL_64_after_swapgs+0x58/0xc6
2019-01-31 15:15:32.729206+0000  localhost com.docker.hyperkit[74256]: [ 1199.642548] Code: 48 89 de 89 c7 e8 12 f9 ff ff 3b 05 77 96 c0 00 7d 1d 48 63 c8 48 8b 55 00 48 03 14 cd e0 33 a4 9b 8b 4a 18 80 e1 01 74 04 f3 90 <eb> f4 eb d1 48 83 c4 10 5b 5d 41 5c 41 5d 41 5e 41 5f c3 0f 1f
2019-01-31 15:16:00.680483+0000  localhost com.docker.hyperkit[74256]: [ 1227.596695] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [sntpc:1417]
2019-01-31 15:16:00.681193+0000  localhost com.docker.hyperkit[74256]: [ 1227.597672] Modules linked in: xfrm_user xfrm_algo
2019-01-31 15:16:00.682248+0000  localhost com.docker.hyperkit[74256]: [ 1227.598383] CPU: 0 PID: 1417 Comm: sntpc Tainted: G             L  4.9.125-linuxkit #1
2019-01-31 15:16:00.682950+0000  localhost com.docker.hyperkit[74256]: [ 1227.599436] Hardware name:  BHYVE, BIOS 1.00 03/14/2014
2019-01-31 15:16:00.683743+0000  localhost com.docker.hyperkit[74256]: [ 1227.600139] task: ffff96c969603000 task.stack: ffffb90d019d8000
2019-01-31 15:16:00.684967+0000  localhost com.docker.hyperkit[74256]: [ 1227.600931] RIP: 0010:[<ffffffff9b13c208>]  [<ffffffff9b13c208>] smp_call_function_many+0x1f1/0x204
2019-01-31 15:16:00.685681+0000  localhost com.docker.hyperkit[74256]: [ 1227.602155] RSP: 0018:ffffb90d019dbdf8  EFLAGS: 00000202
2019-01-31 15:16:00.686633+0000  localhost com.docker.hyperkit[74256]: [ 1227.602869] RAX: 0000000000000001 RBX: ffff96c97fc1a008 RCX: 0000000000000001
2019-01-31 15:16:00.687588+0000  localhost com.docker.hyperkit[74256]: [ 1227.603821] RDX: ffff96c97fc9c918 RSI: 0000000000000000 RDI: ffff96c97fc1a008
2019-01-31 15:16:00.688540+0000  localhost com.docker.hyperkit[74256]: [ 1227.604776] RBP: ffff96c97fc1a000 R08: ffffffffffffffff R09: 000000000000000e
2019-01-31 15:16:00.689491+0000  localhost com.docker.hyperkit[74256]: [ 1227.605727] R10: ffffb90d019dbdf8 R11: 0000000000000000 R12: 0000000000000001
2019-01-31 15:16:00.690443+0000  localhost com.docker.hyperkit[74256]: [ 1227.606679] R13: 0000000000019fc0 R14: 0000000000000000 R15: ffffffff9ba433e0
2019-01-31 15:16:00.691519+0000  localhost com.docker.hyperkit[74256]: [ 1227.607631] FS:  00007f7da32dcb88(0000) GS:ffff96c97fc00000(0000) knlGS:0000000000000000
2019-01-31 15:16:00.692290+0000  localhost com.docker.hyperkit[74256]: [ 1227.608707] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
2019-01-31 15:16:00.693241+0000  localhost com.docker.hyperkit[74256]: [ 1227.609478] CR2: 000000c420177010 CR3: 0000000306a24000 CR4: 0000000000060630
2019-01-31 15:16:00.693526+0000  localhost com.docker.hyperkit[74256]: [ 1227.610429] Stack:
2019-01-31 15:16:00.694595+0000  localhost com.docker.hyperkit[74256]: [ 1227.610715]  ffffffff9b12bd86 00000003017e75f0 ffffffff9b12bd86 0000000000000000
2019-01-31 15:16:00.695663+0000  localhost com.docker.hyperkit[74256]: [ 1227.611783]  0000000000000202 0000000000000000 0000000000000000 0000000000000000
2019-01-31 15:16:00.696739+0000  localhost com.docker.hyperkit[74256]: [ 1227.612851]  ffffffff9b13c239 ffffffff9b13c252 ffffb90d019dbef8 ffffb90d019dbe98
2019-01-31 15:16:00.697081+0000  localhost com.docker.hyperkit[74256]: [ 1227.613927] Call Trace:
2019-01-31 15:16:00.697954+0000  localhost com.docker.hyperkit[74256]: [ 1227.614272]  [<ffffffff9b12bd86>] ? __hrtimer_get_remaining+0x6d/0x6d
2019-01-31 15:16:00.698829+0000  localhost com.docker.hyperkit[74256]: [ 1227.615144]  [<ffffffff9b12bd86>] ? __hrtimer_get_remaining+0x6d/0x6d
2019-01-31 15:16:00.699635+0000  localhost com.docker.hyperkit[74256]: [ 1227.616019]  [<ffffffff9b13c239>] ? smp_call_function+0x1e/0x21
2019-01-31 15:16:00.700365+0000  localhost com.docker.hyperkit[74256]: [ 1227.616825]  [<ffffffff9b13c252>] ? on_each_cpu+0x16/0x40
2019-01-31 15:16:00.701126+0000  localhost com.docker.hyperkit[74256]: [ 1227.617563]  [<ffffffff9b12c392>] ? clock_was_set+0x18/0x1d
2019-01-31 15:16:00.701925+0000  localhost com.docker.hyperkit[74256]: [ 1227.618319]  [<ffffffff9b130d3a>] ? do_settimeofday64+0xe6/0xf2
2019-01-31 15:16:00.702765+0000  localhost com.docker.hyperkit[74256]: [ 1227.619115]  [<ffffffff9b1294f6>] ? do_sys_settimeofday64+0x98/0xf1
2019-01-31 15:16:00.703548+0000  localhost com.docker.hyperkit[74256]: [ 1227.619954]  [<ffffffff9b129607>] ? SyS_settimeofday+0xb8/0xda
2019-01-31 15:16:00.704297+0000  localhost com.docker.hyperkit[74256]: [ 1227.620737]  [<ffffffff9b0033f4>] ? do_syscall_64+0x6f/0x7f
2019-01-31 15:16:00.705227+0000  localhost com.docker.hyperkit[74256]: [ 1227.621487]  [<ffffffff9b7e74ce>] ? entry_SYSCALL_64_after_swapgs+0x58/0xc6
2019-01-31 15:16:00.709061+0000  localhost com.docker.hyperkit[74256]: [ 1227.622415] Code: 48 89 de 89 c7 e8 12 f9 ff ff 3b 05 77 96 c0 00 7d 1d 48 63 c8 48 8b 55 00 48 03 14 cd e0 33 a4 9b 8b 4a 18 80 e1 01 74 04 f3 90 <eb> f4 eb d1 48 83 c4 10 5b 5d 41 5c 41 5d 41 5e 41 5f c3 0f 1f
2019-01-31 15:16:28.660360+0000  localhost com.docker.hyperkit[74256]: [ 1255.576571] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [sntpc:1417]
2019-01-31 15:16:28.661070+0000  localhost com.docker.hyperkit[74256]: [ 1255.577549] Modules linked in: xfrm_user xfrm_algo
2019-01-31 15:16:28.662123+0000  localhost com.docker.hyperkit[74256]: [ 1255.578260] CPU: 0 PID: 1417 Comm: sntpc Tainted: G             L  4.9.125-linuxkit #1
2019-01-31 15:16:28.662825+0000  localhost com.docker.hyperkit[74256]: [ 1255.579311] Hardware name:  BHYVE, BIOS 1.00 03/14/2014
2019-01-31 15:16:28.663618+0000  localhost com.docker.hyperkit[74256]: [ 1255.580013] task: ffff96c969603000 task.stack: ffffb90d019d8000
2019-01-31 15:16:28.664846+0000  localhost com.docker.hyperkit[74256]: [ 1255.580806] RIP: 0010:[<ffffffff9b13c208>]  [<ffffffff9b13c208>] smp_call_function_many+0x1f1/0x204
2019-01-31 15:16:28.665559+0000  localhost com.docker.hyperkit[74256]: [ 1255.582034] RSP: 0018:ffffb90d019dbdf8  EFLAGS: 00000202
2019-01-31 15:16:28.666512+0000  localhost com.docker.hyperkit[74256]: [ 1255.582747] RAX: 0000000000000001 RBX: ffff96c97fc1a008 RCX: 0000000000000001
2019-01-31 15:16:28.667545+0000  localhost com.docker.hyperkit[74256]: [ 1255.583700] RDX: ffff96c97fc9c918 RSI: 0000000000000000 RDI: ffff96c97fc1a008
2019-01-31 15:16:28.668518+0000  localhost com.docker.hyperkit[74256]: [ 1255.584739] RBP: ffff96c97fc1a000 R08: ffffffffffffffff R09: 000000000000000e
2019-01-31 15:16:28.669488+0000  localhost com.docker.hyperkit[74256]: [ 1255.585707] R10: ffffb90d019dbdf8 R11: 0000000000000000 R12: 0000000000000001
2019-01-31 15:16:28.670453+0000  localhost com.docker.hyperkit[74256]: [ 1255.586677] R13: 0000000000019fc0 R14: 0000000000000000 R15: ffffffff9ba433e0
2019-01-31 15:16:28.671559+0000  localhost com.docker.hyperkit[74256]: [ 1255.587642] FS:  00007f7da32dcb88(0000) GS:ffff96c97fc00000(0000) knlGS:0000000000000000
2019-01-31 15:16:28.672341+0000  localhost com.docker.hyperkit[74256]: [ 1255.588749] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
2019-01-31 15:16:28.673317+0000  localhost com.docker.hyperkit[74256]: [ 1255.589530] CR2: 000000c420177010 CR3: 0000000306a24000 CR4: 0000000000060630
2019-01-31 15:16:28.673607+0000  localhost com.docker.hyperkit[74256]: [ 1255.590506] Stack:
2019-01-31 15:16:28.674698+0000  localhost com.docker.hyperkit[74256]: [ 1255.590797]  ffffffff9b12bd86 00000003017e75f0 ffffffff9b12bd86 0000000000000000
2019-01-31 15:16:28.675850+0000  localhost com.docker.hyperkit[74256]: [ 1255.591887]  0000000000000202 0000000000000000 0000000000000000 0000000000000000
2019-01-31 15:16:28.676962+0000  localhost com.docker.hyperkit[74256]: [ 1255.593041]  ffffffff9b13c239 ffffffff9b13c252 ffffb90d019dbef8 ffffb90d019dbe98
2019-01-31 15:16:28.677311+0000  localhost com.docker.hyperkit[74256]: [ 1255.594151] Call Trace:
2019-01-31 15:16:28.678196+0000  localhost com.docker.hyperkit[74256]: [ 1255.594505]  [<ffffffff9b12bd86>] ? __hrtimer_get_remaining+0x6d/0x6d
2019-01-31 15:16:28.679071+0000  localhost com.docker.hyperkit[74256]: [ 1255.595388]  [<ffffffff9b12bd86>] ? __hrtimer_get_remaining+0x6d/0x6d
2019-01-31 15:16:28.679868+0000  localhost com.docker.hyperkit[74256]: [ 1255.596261]  [<ffffffff9b13c239>] ? smp_call_function+0x1e/0x21
2019-01-31 15:16:28.680595+0000  localhost com.docker.hyperkit[74256]: [ 1255.597057]  [<ffffffff9b13c252>] ? on_each_cpu+0x16/0x40
2019-01-31 15:16:28.681345+0000  localhost com.docker.hyperkit[74256]: [ 1255.597784]  [<ffffffff9b12c392>] ? clock_was_set+0x18/0x1d
2019-01-31 15:16:28.682139+0000  localhost com.docker.hyperkit[74256]: [ 1255.598534]  [<ffffffff9b130d3a>] ? do_settimeofday64+0xe6/0xf2
2019-01-31 15:16:28.682980+0000  localhost com.docker.hyperkit[74256]: [ 1255.599329]  [<ffffffff9b1294f6>] ? do_sys_settimeofday64+0x98/0xf1
2019-01-31 15:16:28.683764+0000  localhost com.docker.hyperkit[74256]: [ 1255.600169]  [<ffffffff9b129607>] ? SyS_settimeofday+0xb8/0xda
2019-01-31 15:16:28.684523+0000  localhost com.docker.hyperkit[74256]: [ 1255.600962]  [<ffffffff9b0033f4>] ? do_syscall_64+0x6f/0x7f
2019-01-31 15:16:28.685457+0000  localhost com.docker.hyperkit[74256]: [ 1255.601716]  [<ffffffff9b7e74ce>] ? entry_SYSCALL_64_after_swapgs+0x58/0xc6
2019-01-31 15:16:28.689288+0000  localhost com.docker.hyperkit[74256]: [ 1255.602646] Code: 48 89 de 89 c7 e8 12 f9 ff ff 3b 05 77 96 c0 00 7d 1d 48 63 c8 48 8b 55 00 48 03 14 cd e0 33 a4 9b 8b 4a 18 80 e1 01 74 04 f3 90 <eb> f4 eb d1 48 83 c4 10 5b 5d 41 5c 41 5d 41 5e 41 5f c3 0f 1f
2019-01-31 15:16:56.640280+0000  localhost com.docker.hyperkit[74256]: [ 1283.556490] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [sntpc:1417]
2019-01-31 15:16:56.640994+0000  localhost com.docker.hyperkit[74256]: [ 1283.557469] Modules linked in: xfrm_user xfrm_algo
2019-01-31 15:16:56.642085+0000  localhost com.docker.hyperkit[74256]: [ 1283.558184] CPU: 0 PID: 1417 Comm: sntpc Tainted: G             L  4.9.125-linuxkit #1
2019-01-31 15:16:56.642830+0000  localhost com.docker.hyperkit[74256]: [ 1283.559276] Hardware name:  BHYVE, BIOS 1.00 03/14/2014
2019-01-31 15:16:56.643644+0000  localhost com.docker.hyperkit[74256]: [ 1283.560020] task: ffff96c969603000 task.stack: ffffb90d019d8000
2019-01-31 15:16:56.644872+0000  localhost com.docker.hyperkit[74256]: [ 1283.560832] RIP: 0010:[<ffffffff9b13c208>]  [<ffffffff9b13c208>] smp_call_function_many+0x1f1/0x204
2019-01-31 15:16:56.645589+0000  localhost com.docker.hyperkit[74256]: [ 1283.562060] RSP: 0018:ffffb90d019dbdf8  EFLAGS: 00000202
2019-01-31 15:16:56.646543+0000  localhost com.docker.hyperkit[74256]: [ 1283.562777] RAX: 0000000000000001 RBX: ffff96c97fc1a008 RCX: 0000000000000001
2019-01-31 15:16:56.647644+0000  localhost com.docker.hyperkit[74256]: [ 1283.563731] RDX: ffff96c97fc9c918 RSI: 0000000000000000 RDI: ffff96c97fc1a008
2019-01-31 15:16:56.648601+0000  localhost com.docker.hyperkit[74256]: [ 1283.564833] RBP: ffff96c97fc1a000 R08: ffffffffffffffff R09: 000000000000000e
2019-01-31 15:16:56.649557+0000  localhost com.docker.hyperkit[74256]: [ 1283.565789] R10: ffffb90d019dbdf8 R11: 0000000000000000 R12: 0000000000000001
2019-01-31 15:16:56.650518+0000  localhost com.docker.hyperkit[74256]: [ 1283.566745] R13: 0000000000019fc0 R14: 0000000000000000 R15: ffffffff9ba433e0
2019-01-31 15:16:56.651613+0000  localhost com.docker.hyperkit[74256]: [ 1283.567707] FS:  00007f7da32dcb88(0000) GS:ffff96c97fc00000(0000) knlGS:0000000000000000
2019-01-31 15:16:56.652399+0000  localhost com.docker.hyperkit[74256]: [ 1283.568801] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
2019-01-31 15:16:56.653366+0000  localhost com.docker.hyperkit[74256]: [ 1283.569587] CR2: 000000c420177010 CR3: 0000000306a24000 CR4: 0000000000060630
2019-01-31 15:16:56.653656+0000  localhost com.docker.hyperkit[74256]: [ 1283.570554] Stack:
2019-01-31 15:16:56.654743+0000  localhost com.docker.hyperkit[74256]: [ 1283.570845]  ffffffff9b12bd86 00000003017e75f0 ffffffff9b12bd86 0000000000000000
2019-01-31 15:16:56.655829+0000  localhost com.docker.hyperkit[74256]: [ 1283.571931]  0000000000000202 0000000000000000 0000000000000000 0000000000000000
2019-01-31 15:16:56.656915+0000  localhost com.docker.hyperkit[74256]: [ 1283.573017]  ffffffff9b13c239 ffffffff9b13c252 ffffb90d019dbef8 ffffb90d019dbe98
2019-01-31 15:16:56.657262+0000  localhost com.docker.hyperkit[74256]: [ 1283.574103] Call Trace:
2019-01-31 15:16:56.658140+0000  localhost com.docker.hyperkit[74256]: [ 1283.574453]  [<ffffffff9b12bd86>] ? __hrtimer_get_remaining+0x6d/0x6d
2019-01-31 15:16:56.659017+0000  localhost com.docker.hyperkit[74256]: [ 1283.575330]  [<ffffffff9b12bd86>] ? __hrtimer_get_remaining+0x6d/0x6d
2019-01-31 15:16:56.659825+0000  localhost com.docker.hyperkit[74256]: [ 1283.576206]  [<ffffffff9b13c239>] ? smp_call_function+0x1e/0x21
2019-01-31 15:16:56.660566+0000  localhost com.docker.hyperkit[74256]: [ 1283.577014]  [<ffffffff9b13c252>] ? on_each_cpu+0x16/0x40
2019-01-31 15:16:56.661328+0000  localhost com.docker.hyperkit[74256]: [ 1283.577755]  [<ffffffff9b12c392>] ? clock_was_set+0x18/0x1d
2019-01-31 15:16:56.662139+0000  localhost com.docker.hyperkit[74256]: [ 1283.578518]  [<ffffffff9b130d3a>] ? do_settimeofday64+0xe6/0xf2
2019-01-31 15:16:56.662992+0000  localhost com.docker.hyperkit[74256]: [ 1283.579328]  [<ffffffff9b1294f6>] ? do_sys_settimeofday64+0x98/0xf1
2019-01-31 15:16:56.663788+0000  localhost com.docker.hyperkit[74256]: [ 1283.580182]  [<ffffffff9b129607>] ? SyS_settimeofday+0xb8/0xda
2019-01-31 15:16:56.664549+0000  localhost com.docker.hyperkit[74256]: [ 1283.580977]  [<ffffffff9b0033f4>] ? do_syscall_64+0x6f/0x7f
2019-01-31 15:16:56.665496+0000  localhost com.docker.hyperkit[74256]: [ 1283.581740]  [<ffffffff9b7e74ce>] ? entry_SYSCALL_64_after_swapgs+0x58/0xc6
2019-01-31 15:16:56.669393+0000  localhost com.docker.hyperkit[74256]: [ 1283.582684] Code: 48 89 de 89 c7 e8 12 f9 ff ff 3b 05 77 96 c0 00 7d 1d 48 63 c8 48 8b 55 00 48 03 14 cd e0 33 a4 9b 8b 4a 18 80 e1 01 74 04 f3 90 <eb> f4 eb d1 48 83 c4 10 5b 5d 41 5c 41 5d 41 5e 41 5f c3 0f 1f

Steps to reproduce the behavior

  1. Run Docker for anything from 10 minutes to 24h on my Mac ;-)
Spareo commented 5 years ago

How do you disable Kubernetes?

Settings --> Kubernetes --> Uncheck Enable Kubernetes

And is it enabled by default when you install Docker, or do you enable it manually first?

On OSX it was not enabled by default

mouse07410 commented 5 years ago

On OSX it was not enabled by default

So, if I'm on OSX, this cannot be the cause of my problem, as I never enabled Kubernetes.

alvises commented 5 years ago

I'm on macOS as well, I enabled it myself since I use k8s most of the time. ᐧ

On Mon, 27 May 2019 at 19:04, Mouse notifications@github.com wrote:

On OSX it was not enabled by default

So, if I'm on OSX, this cannot be the cause of my problem, as I never enabled Kubernetes.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/docker/for-mac/issues/3499?email_source=notifications&email_token=AADWVRIZNQN6YOQPYJVTXZTPXQPDBA5CNFSM4GTSEEEKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODWKJPEQ#issuecomment-496277394, or mute the thread https://github.com/notifications/unsubscribe-auth/AADWVROK4KH4O7M5EQYG5S3PXQPDBANCNFSM4GTSEEEA .

-- Alvise Susmel

Code poet at Poeticoding Ltd. +44 (0) 7546 116951 www.poeticoding.com

akilman commented 5 years ago

Can confirm. My CPU usage was through the roof, and disabling my local k8s cluster has things looking normal again.

$ docker --version
Docker version 18.09.2, build 6247962

K8s version: v1.10.11

vladdsm commented 5 years ago

same issue when:

no issue when:

Considering above, I believe that issue is linked to the volumes mapping feature. Probably docker is synchronising the underlying volumes [key -v /host/path:/container/path] too fast??

Up to my understanding this problem is exclusive feature of Mac. This link explains some development efforts https://docs.docker.com/docker-for-mac/osxfs/

ibejohn818 commented 5 years ago

Can confirm the sudden CPU pegging issue on my setup. Using docker-compose running various combinations of stacks (nginx/python/rust/go/php etc). It intermittently happens, killing the current stack (docker-compose down ctrl+c) and utilization usually drops (i'd say 8/10... I've had some cases I had to kill the docker-for-mac client ) Here's my info


Using *.raw Kubernetes: Off CPUs 4, Mem: 4gb, Swap: 1gb Mojave MBP 2019 15" Screencap with my machine and client versions: https://imgur.com/RWTOYdT

To add, I also dev the same stacks/code-bases on an X99 (5930k) running docker-ce on ubuntu bionic and have yet to get the CPU pegging issue.

UPDATE 2019-06-22 I've gone back to using docker-sync for my read/write attached volumes (which in the current application I'm dev'ing on was approx. 5 vols to 5of8 containers) and have had no issues with runaway/pegged CPU since. Will try and look into if volumes were the issue (APFS is a pretty junk FS). I'd suggest for anyone to try using docker-sync for their volumes (NOTE: not compatible on linux so have to maintain a separate docker-compose yaml for mac + ubuntu ) (I'd also suggest using RVM so you don't have to install any global ruby packages to use docker-sync) I'll update in a few days...

UPDATE: 2019-06-24 I've tried the same app/setup on my 2014 mbp and seeing same/as-good results as the 2019 mbp. Dev'd for approx. 3 hrs with no issue (previous i'd usually see issues every 10-30min) Screencap with info: https://imgur.com/rZKzn04 I'll update in a few days... (when i get some downtime i'll also see if i can profile the FS to see if volumes are causing the runaway/pegged cpu)

UPDATE: 2019-07-11 No problems after changing to docker-sync VS volumes mounted directly from macos file system. I've noticed that when I do use volumes mounted directly from macos and there is any moderate amount of IO (IE: compiling code or changing git branches that add/remove 40+ files) that 9/10 hyperkit starts pinning my CPU until I kill the containers with the mounted volumes. UPDATE: 2019-07-12 I noticed that any moderate amount of IO even outside of the context of a volume but in the "FIle Sharing" paths of your docker configuration causes hyperkit to peg the CPU. IE: I have my /home/{user}/Projects as my "File Sharing" path in the docker config, I did not have any volumes mounted and unzipped a directory with about 15000 files in my projects path and that was causing the hyperkit CPU pegging.. I was able to replicate it multiple times

borttrob commented 5 years ago

Tried multiple suggestions from this Thread. Something has seemingly worked, as hyperkit is at 30% from 300% now. I did the following:

Suggestions from @peterataylor's link, especially

Removed the Docker.raw as suggested by @weburnit

(Kubernetes was disabled the whole time on my machine)

vogelito commented 5 years ago

Thanks @borttrob - this is a PITA for me right now. Will try your suggestions.

jca-agnitio commented 5 years ago

I have the same issue, unfortunately the only thing that helps is "kill -9". I noticed that this happens when VMWare workstation is running at the same time with Docker in same host. Could be that docker had allocated 4 CPUs and my VM (Ubuntu) had also 4 CPUS leaving nothing available.

UPDATE (16-08-2019) : It seems this issue is not happening to me anymore. Engine: 19.03.1 Compose: 1.24.1 Kubernetes: v1.14.3

JamesonNetworks commented 5 years ago

There are two other issues that seem to be similar to this at https://github.com/docker/for-mac/issues/2582 and https://github.com/docker/for-mac/issues/1759

Edit: Web of issues: Possibly related to: https://github.com/docker/for-mac/issues/1759 https://github.com/docker/for-mac/issues/2582 https://github.com/docker/for-mac/issues/2926 https://github.com/docker/for-mac/issues/3499

noizo commented 5 years ago

MacBook Pro 15' from 2019: What helped me:

bryanhuntesl commented 5 years ago

MacBook Pro 15' from 2019: What helped me:

For me, simply choosing - "Reset" -> "Reset disk image" in the Docker for mac GUI resolved the issue. I'm running 2.0.5.0 (35318).

I was seeing 380% CPU usage and the frequent slowdown of desktop applications.

Looked inside the VM - top three processes were using respectively, 23, 10, and 11 % of VM CPU - they were kube-apiserver, kube-controller-manager, and etc - so it wasn't a container I'd deployed chewing up resources.

Seems like disk storage is an area containing some pervasive and persistent bugs.

PiTiLeZarD commented 5 years ago

Not sure if I'm helping, but what I had here was:

I stopped K8s and all processes/cores back to 1-5%, docker-compose super fast

It's not really a solution but it helps with the space heater issue in my case!

whoisstan commented 5 years ago

I have had the same problem, finally switched to docker-sync, little setup needed, CPU usage for my docker-compose app went from 450% to 30% using even more cores.

http://docker-sync.io/

guice commented 5 years ago

Ran into the same problem, too.

My Solution was: quit docker, force quick hyperkit within the process manager, then restart Docker.

Hyperkit showed running for 20+ days, suggesting it buggered up before my reset and never successfully stopped itself. Force quit allowed it to stop.

This is not a solution. It's just a temporary solution worked for me.

I'm adding my +1 to this issue as I've seen it as well.

snackycracky commented 5 years ago

thanks @whoisstan http://docker-sync.io/ helped me as well :)

I followed the instructions starting at the point where I needed to install Xcode because I had some ruby problems after running sudo gem install docker-sync. Namely

mkmf.rb can't find header files for ruby at /System/Library/Frameworks/Ruby.framework/Versions/2.3/usr/lib/ruby/include/ruby.h

I opened Xcode (which had to install something) and then went to preferences -> Locations -> Command-Line-Tools. The instructions I found were here: https://stackoverflow.com/a/56473855/170881 I was then able to run docker-sync start after I followed the instructions on https://docker-sync.readthedocs.io/en/latest/getting-started/configuration.html I had to create a docker-sync.yml file and fill it with the images that are mounted. For example the service services/matching had now a name of matching-sync in that config. I then had to update the docker-compose.yml to mount the volume from an “external” volume:

Screenshot 2019-07-20 00 28 03

The syncing of the files seem too slow, after I added all the services. I extended the docker-sync.yml configuration to exclude certain directories with a lot of files like node_modules and such.

Screenshot 2019-07-20 15 53 37

And now I had a CPU load ~19% with Docker Desktop 2.0.0.3 stable with 6 CPUs and 8Gb memory and Swap set to 3Gb on a 2.9 Ghz i7 with 16G RAM

Screenshot 2019-07-20 15 56 48

nickdnk commented 5 years ago

+1. Latest macOS (just updated) 10.14.6 - and Docker 2.0.0.3 (31259).

antimoroma commented 5 years ago

+1 Latest macOS (just updated) 10.14.6 - and Docker 2.0.0.3 (31259).

wadechandler commented 5 years ago

I confirm what @guice said https://github.com/docker/for-mac/issues/3499#issuecomment-512976590 it is hyperkit. I notice even when I use the hyperkit which comes with docker from minikube similar results, so have only been starting minikube when I need to actually work with something. Luckily for me it is only consuming 30 to 40% when nothing running other than hyperkit but still high for no running pods.

belgianwolfie commented 5 years ago

I finally managed to tame my Docker desktop app. Hyperkit used to take up around 100 - 300% of CPU and has now been brought down to spikes of 60% only when actively browsing pages.

What helped me - but I'm sure it'll be different for everyone (as it has been for me with all the proposed 'solutions' so far).

By default, Docker for Mac comes with /Users, /Volumes, /private, and /tmp directories available to bind mount into Docker containers. Remove all of these.

To do this, go to Docker > Preferences > File Sharing and removed said directories

Kudos for the solution go to this page (I only used the quoted portion, but anyone else may benefit)

As this seems to be helping some people I'm adding some other sidenotes:

samsonnguyen commented 5 years ago

@belgianwolfie 's fix is not an actual fix if you need to bind mount a directory inside of a container that resides within one of those file sharing directories.

ncri commented 5 years ago

@belgianwolfie unfortunately this doesn't work for me, i get:

Cannot change shared directories Cannot read response

ncri commented 5 years ago

Ah seems my docker UI was in a bad state. After quitting and starting docker again i was able to remove the directories.

kylemeenehan commented 5 years ago

I was getting this when running a Node app and a MongoDB instance with docker-compose. Changing the volumes to use a delegated configuration worked for me and resulted in a drastic drop in CPU usage. See this article: https://docs.docker.com/docker-for-mac/osxfs-caching/#delegated

This is my docker-compose.yml after the change, note the :delegated after the volume binding:

version: '3.4'

services:
  mongo:
    image: mongo:3.4-jessie
    volumes:
      - ./data:/data/db:delegated
    ports:
      - "27017:27017"
  web:
    build:
      context: .
      target: dev
    volumes:
      - .:/code:delegated
    ports:
      - "3000:3000"
      - "9229:9229"
    depends_on:
      - mongo

I was worried whether this might affect my workflow with nodemon for restarting after file changes, but it's all working fine!

whoisstan commented 5 years ago

hi kyle,

i have a similar setup for development to yours, except that I have 5 node components, not just 'web'. even with using delegated on the fastest macbook pro i easily go north of 500% of cpu usage, with docker-sync it's less then 50%, of course docker-sync has a whole bunch of sync problems as well.I am using a shell script to manually clean and start docker-sync, seems clumsy but still better then the CPU being on a constant high speed sprint.

fswatch app/ | while read num ; do docker-sync clean && docker-sync start done

It's all very annoying to say the least.

stan

On Thu, Aug 15, 2019 at 6:43 AM Kyle Meenehan notifications@github.com wrote:

I was getting this when running a Node app and a MongoDB instance with docker-compose. Changing the volumes to use a delegated configuration worked for me and resulted in a drastic drop in CPU usage. See this article: https://docs.docker.com/docker-for-mac/osxfs-caching/#delegated

This is my docker-compose.yml after the change, note the :delegated after the volume binding:

version: '3.4'

services: mongo: image: mongo:3.4-jessie volumes:

  • ./data:/data/db:delegated ports:
  • "27017:27017" web: build: context: . target: dev volumes:
  • .:/code:delegated ports:
  • "3000:3000"
  • "9229:9229" depends_on:
  • mongo

I was worried whether this might affect my workflow with nodemon for restarting after file changes, but it's all working fine!

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/docker/for-mac/issues/3499?email_source=notifications&email_token=AABE3CHIXSZFIRQZ3NIQENTQEUXM5A5CNFSM4GTSEEEKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD4LPQKQ#issuecomment-521599018, or mute the thread https://github.com/notifications/unsubscribe-auth/AABE3CFRLCEKSAK23YGOHSLQEUXM5ANCNFSM4GTSEEEA .

-- "Local color. Soak it up" Virginia Vidaura

http://www.merkwelt.com/people/stan/

shadowbrush commented 5 years ago

In my case it was caused by a postgresql container with a shared data directory on the host. After eliminating this, the CPU usage went from a consistent >300% to a very satisfying <20%.

hochbergg commented 5 years ago

I think I may have found a reason for high CPU usage in certain cases: swapfile usage.

I have a docker-for-mac setup with Kubernetes (built in) and many pods on a Macbook Pro, and CPU was hitting 200% constantly and 400% sometimes (on 4 corse), making everything non-responsive.

I opened a shell on the VM itself (using docker run --privileged --pid=host -it alpine:3.8 nsenter -t 1 -m -u -n -i sh) and ran top to see what was going on. I noticed 25% virtual CPU on the swap service which made me suspicious.

I then raised my docker's RAM to 8GB and dropped Swap to 512MB, and now CPU usage (while not totally gone) is more like 60% (out of 400%).

I don't know how swap is implemented in Hyperkit/Docker-for-mac, but as both swap and disk performance are sensitive issues, could this somehow be related?

mschipperheyn commented 5 years ago

I had this problem as well and it went away after ensuring that native bindings were installed. You can run a native bind install by running npm rebuild (even if you use yarn)

artembatura commented 5 years ago

@shadowbrush How you eliminated this?

shadowbrush commented 5 years ago

@artemirq I'm using a postgres database, and linking its data dir to a host dir caused the CPU usage. Excerpt from docker-compose.yml:

High CPU (using linked data dir on host):

postgres:
  ...
  volumes:
    - ./data/db:/var/lib/postgresql/data

CPU issue resolved (using a docker volume):

postgres:
  ...
  volumes:
    - db:/var/lib/postgresql/data
...
volumes:
  db:

At least that's one way to deal with what caused the CPU issue in my situation. I ended up running the database on the host entirely, since it's used by other docker-compose projects as well.

zhaoqin-github commented 5 years ago

I have similar issue

ozandogrultan commented 5 years ago

Unfortunately, none if these worked for me. Still getting 100%+ CPU usage. Are there any plans for a permanent solution?

stephenc commented 5 years ago

I’m starting to think the permanent solution is to uninstall Docker 🙄

bryanhuntesl commented 5 years ago

I’m starting to think the permanent solution is to uninstall Docker 🙄

Ha we both know that's not going to happen, at least not on OSX - you're going to have to find a way to run Docker as part of your development environment without being driven insane.

Perhaps we're expecting too much of Docker for Mac. Maybe create a virtual environment with VMware?

With VMWare/Centos 7 I'm observing (iotop) a write speed > 200M/s on an aftermarket SSD - it''s worth noting that a lot of that may be memory buffering, I haven't investigated...

(dd if=/dev/sda of=/dev/foo count=1000000000)

Another issue with docker for mac is the lack of build secret support - it's painful to build stuff on OSX where you have to resort to all sorts of (and I bet we'll see vulns in the future) dumb hacks to share SSH or other credentials with your docker build.

Then again, do you want to buy VMware licenses for your team? Perhaps it's more secure anyway?

I'll mention at this point, the experience of running VirtualBox under OSX is underwhelming - you don't know what pain is until you're experiencing a kernel panic every 3 hours - maybe the quality has improved in the 3 years since I ditched it, I don't know.

What kind of IO performance do you see if you execute a similar microbenchmark inside a container running under Docker for Mac ? Would executing a command like that lock up the CPU?

insidewhy commented 5 years ago

At my job they are using docker and most developers are using Mac, so I'm having to support them. They are all seeing constant 700% CPU usage from docker. The containers themselves are all using 2-20%. Docker just isn't usable on Mac IMO.

kjella commented 4 years ago

My current fix is to open the Docker preferences/settings window in OSX. By just doing that my docker process usage is reduced drastically. If I close this window, the process usage increases to 190% again.

devusvulgaris commented 4 years ago

I can confirm that opening Docker preferences decreases CPU usage to 15%-25%. And closing preferences window increases CPU usage by Docker (not com.docker.hyperkit) back to ~200%.

stephenc commented 4 years ago

Ok a solution! Win!

amok commented 4 years ago

confirm @kjella 's "open settings" solution too

Shahor commented 4 years ago

Not sure if trolling 🤔

insidewhy commented 4 years ago

Opening the setting does not help for me. Only running on Linux as opposed to Mac helps.

webartistse commented 4 years ago

This is a nightmare! Mac users can get more attention from Valve which is bad by default.

ncri commented 4 years ago

Odd, for me this issue is almost completely gone after i removed those file sharing directories mentioned higher up here. Every now and then it still appears (like once every 2 weeks), but after I restart my docker sync stack it is gone again. Working with docker is super smooth on mac for me now.

insidewhy commented 4 years ago

If I run watchman inside a container on a directory with more than one hundred or so files I get the 700% usage constantly from hyperkit. If I use chokidar to watch the exact same directory then I get 20%.

None of the proposed solutions in this issue work for me. I just can't use Watchman in docker mac.

insidewhy commented 4 years ago

Even when I'm not getting the 700% fs usage the filesystem under docker mac is just painfully slow. I can see why all the developers who use Mac at my job are reluctant to use docker. The developers using Linux have a significantly better experience.

jeff-h commented 4 years ago

@ohjames at the risk of going off topic, what do the Mac devs use instead?

insidewhy commented 4 years ago

@jeff-h right now they suffer. They wait for two minutes to test every single code change while the Linux Devs wait for less than a second. Although I'm finishing off a change to ts-node that caches every source file that was include outside of a bind mount. That way they will suffer a little less.

ncri commented 4 years ago

You guys are not using docker-sync? On the mac it's a must i think.

insidewhy commented 4 years ago

@ncri It slowed down our first load horrendously. Our new solution using a modified ts-node provides the same benefits on reload without the initial hit.

ncri commented 4 years ago

@ohjames oh, okay, that is odd, for me the first load you is very fast. Probably depends on the workload and also machine you are using. I run a docker-compose file with 9 services which start up quickly with docker-sync.