Re: What are thoses [btrfs-cache-nnn] kernel threads ?

[Josef Bacik <josef@redhat.com>]

On Wed, May 18, 2011 at 10:37:17PM -0400, Christian Robert wrote:
> hi,
> 
>  everyday at around 17:00, but today at 18:38 I start
>  a multithread job (a la make -j4) who rsync
>  257 huge directory from a remote host to my
>  machine (at kernel 2.6.39-rc7 since yesterday)
> 
> below is the load average on the machine
> 
> 2011-05-18 18:36 -> 0.00 0.11 0.13 1/218 1923
> 2011-05-18 18:37 -> 0.00 0.09 0.13 1/218 1923
> 2011-05-18 18:38 -> 0.42 0.17 0.15 1/240 2275  <- job started here
> 2011-05-18 18:39 -> 0.62 0.26 0.18 1/243 2287
> 2011-05-18 18:40 -> 1.78 0.64 0.32 1/244 2288
> 2011-05-18 18:41 -> 1.45 0.76 0.38 1/244 2297
> 2011-05-18 18:42 -> 1.94 1.02 0.49 1/244 2310
> 2011-05-18 18:43 -> 2.27 1.28 0.62 1/242 2325
> 2011-05-18 18:44 -> 2.39 1.45 0.71 1/247 2333
> 2011-05-18 18:45 -> 2.39 1.61 0.81 1/246 2359
> 2011-05-18 18:46 -> 3.22 1.95 0.98 1/248 2375
> 2011-05-18 18:47 -> 3.16 2.17 1.12 1/247 2386
> 2011-05-18 18:48 -> 3.40 2.39 1.25 1/249 2394
> 2011-05-18 18:49 -> 4.33 2.82 1.47 1/249 2395
> 2011-05-18 18:50 -> 3.93 3.01 1.63 1/246 2406
> 2011-05-18 18:51 -> 3.81 3.14 1.75 1/248 2410
> 2011-05-18 18:52 -> 3.92 3.32 1.90 1/247 2417
> 2011-05-18 18:53 -> 2.62 3.06 1.90 1/246 2431
> 2011-05-18 18:54 -> 3.52 3.22 2.03 1/248 2433
> 2011-05-18 18:55 -> 3.84 3.38 2.16 1/247 2439
> 2011-05-18 18:56 -> 2.91 3.26 2.20 1/245 2450
> 2011-05-18 18:57 -> 2.75 3.11 2.22 1/248 2457
> 2011-05-18 18:58 -> 3.59 3.29 2.33 1/248 2458
> 2011-05-18 18:59 -> 3.41 3.30 2.40 1/248 2468
> 2011-05-18 19:00 -> 3.76 3.40 2.49 1/247 2477
> 2011-05-18 19:01 -> 4.28 3.60 2.61 1/248 2488
> 2011-05-18 19:02 -> 4.06 3.67 2.70 1/247 2502
> 2011-05-18 19:03 -> 2.16 3.21 2.60 1/244 2515
> 2011-05-18 19:04 -> 2.81 3.17 2.62 1/247 2518
> 2011-05-18 19:05 -> 3.23 3.24 2.68 1/246 2522
> 2011-05-18 19:06 -> 3.53 3.32 2.74 1/246 2544
> 2011-05-18 19:07 -> 2.89 3.13 2.71 1/245 2550
> 2011-05-18 19:08 -> 3.68 3.28 2.79 1/247 2557
> 2011-05-18 19:09 -> 4.47 3.62 2.94 2/242 2571
> 2011-05-18 19:10 -> 3.20 3.39 2.90 1/244 2577
> 2011-05-18 19:11 -> 5.35 4.03 3.16 1/244 2584
> 2011-05-18 19:12 -> 5.07 4.20 3.26 3/245 2588
> 2011-05-18 19:13 -> 2.69 3.72 3.16 1/241 2602
> 2011-05-18 19:14 -> 3.37 3.70 3.19 1/244 2605
> 2011-05-18 19:15 -> 3.55 3.71 3.22 1/242 2611
> 2011-05-18 19:16 -> 2.94 3.48 3.18 1/243 2621
> 2011-05-18 19:17 -> 3.15 3.45 3.19 1/241 2630
> 2011-05-18 19:18 -> 3.02 3.37 3.17 1/242 2639
> 2011-05-18 19:19 -> 3.47 3.40 3.19 1/243 2649
> 2011-05-18 19:20 -> 3.71 3.46 3.23 1/243 2650
> 2011-05-18 19:21 -> 2.64 3.22 3.16 1/241 2664
> 2011-05-18 19:22 -> 3.48 3.31 3.19 1/244 2671
> 2011-05-18 19:23 -> 4.57 3.63 3.31 1/243 2675
> 2011-05-18 19:24 -> 4.06 3.66 3.34 1/242 2684
> 2011-05-18 19:25 -> 5.34 4.06 3.49 1/250 2699
> 2011-05-18 19:26 -> 6.18 4.57 3.71 1/244 2707
> 2011-05-18 19:27 -> 5.21 4.54 3.75 1/244 2711
> 2011-05-18 19:28 -> 4.17 4.37 3.74 1/244 2721
> 2011-05-18 19:29 -> 4.14 4.34 3.77 1/243 2728
> 2011-05-18 19:30 -> 4.52 4.40 3.82 1/243 2734
> 2011-05-18 19:31 -> 4.74 4.50 3.90 1/244 2743
> 2011-05-18 19:32 -> 5.09 4.60 3.97 3/244 2754
> 2011-05-18 19:33 -> 4.59 4.60 4.01 1/242 2765
> 2011-05-18 19:34 -> 4.39 4.53 4.02 1/243 2769
> 2011-05-18 19:35 -> 4.75 4.60 4.08 1/243 2773
> 2011-05-18 19:36 -> 4.98 4.66 4.13 2/245 2783
> 2011-05-18 19:37 -> 4.29 4.55 4.13 1/245 2797
> 2011-05-18 19:38 -> 7.16 5.27 4.39 1/243 2809
> 2011-05-18 19:39 -> 6.31 5.31 4.46 1/247 2815
> 2011-05-18 19:40 -> 6.29 5.40 4.54 1/251 2827
> 2011-05-18 19:41 -> 6.31 5.66 4.69 2/245 2838
> 2011-05-18 19:42 -> 4.43 5.25 4.61 1/243 2848
> 2011-05-18 19:43 -> 5.13 5.30 4.67 1/247 2856
> 2011-05-18 19:44 -> 5.39 5.31 4.71 1/243 2866
> 2011-05-18 19:45 -> 3.95 4.94 4.62 2/242 2874
> 2011-05-18 19:46 -> 4.59 4.99 4.66 1/243 2884
> 2011-05-18 19:47 -> 4.97 5.06 4.71 1/243 2889
> 2011-05-18 19:48 -> 5.51 5.25 4.79 1/245 2899
> 2011-05-18 19:49 -> 5.19 5.22 4.82 1/242 2905
> 2011-05-18 19:50 -> 5.21 5.18 4.82 2/246 2911
> 2011-05-18 19:51 -> 6.80 5.55 4.97 1/248 2918
> 2011-05-18 19:52 -> 6.11 5.67 5.05 1/241 2924
> 2011-05-18 19:53 -> 5.89 5.72 5.11 3/240 2938
> 2011-05-18 19:54 -> 3.96 5.20 4.96 1/241 2944
> 2011-05-18 19:55 -> 5.03 5.32 5.02 1/244 2952
> 2011-05-18 19:56 -> 4.81 5.22 5.01 1/243 2954
> 2011-05-18 19:57 -> 5.01 5.22 5.03 1/242 2958
> 2011-05-18 19:58 -> 4.82 5.15 5.02 1/242 2965
> 2011-05-18 19:59 -> 4.37 4.99 4.98 1/241 2978
> 2011-05-18 20:00 -> 4.93 4.98 4.97 3/243 2985
> 2011-05-18 20:01 -> 4.56 4.85 4.93 1/243 2995
> 2011-05-18 20:02 -> 4.41 4.76 4.89 2/243 3012
> 2011-05-18 20:03 -> 4.06 4.59 4.82 2/245 3022
> 2011-05-18 20:04 -> 3.94 4.47 4.77 2/243 3029
> 2011-05-18 20:05 -> 4.85 4.60 4.79 1/243 3034
> 2011-05-18 20:06 -> 4.90 4.71 4.82 1/242 3047
> 2011-05-18 20:07 -> 4.50 4.61 4.78 2/244 3055
> 2011-05-18 20:08 -> 4.06 4.48 4.72 2/245 3061
> 2011-05-18 20:09 -> 4.34 4.52 4.72 1/242 3070
> 2011-05-18 20:10 -> 4.95 4.63 4.75 1/246 3077
> 2011-05-18 20:11 -> 4.27 4.55 4.72 1/241 3089
> 2011-05-18 20:12 -> 4.44 4.58 4.72 1/241 3098
> 2011-05-18 20:13 -> 5.13 4.77 4.78 1/242 3104
> 2011-05-18 20:14 -> 4.20 4.56 4.70 1/245 3118
> 2011-05-18 20:15 -> 4.20 4.51 4.68 1/241 3128
> 2011-05-18 20:16 -> 4.43 4.52 4.67 1/244 3137
> 2011-05-18 20:17 -> 4.96 4.71 4.73 1/244 3146
> 2011-05-18 20:18 -> 5.36 4.85 4.78 3/246 3151
> 2011-05-18 20:19 -> 4.25 4.65 4.72 1/245 3165
> 2011-05-18 20:20 -> 4.75 4.77 4.76 1/243 3173
> 2011-05-18 20:21 -> 5.42 4.94 4.81 1/241 3187
> 2011-05-18 20:22 -> 3.58 4.49 4.67 3/243 3196
> 2011-05-18 20:23 -> 4.27 4.54 4.67 1/243 3199
> 2011-05-18 20:24 -> 4.26 4.53 4.67 1/243 3212
> 2011-05-18 20:25 -> 4.68 4.59 4.68 1/244 3224
> 2011-05-18 20:26 -> 4.50 4.59 4.68 1/242 3231
> 2011-05-18 20:27 -> 5.09 4.74 4.72 1/243 3243
> 2011-05-18 20:28 -> 5.09 4.76 4.72 1/246 3256
> 2011-05-18 20:29 -> 5.30 4.87 4.76 1/243 3260
> 2011-05-18 20:30 -> 6.75 5.37 4.94 1/244 3270
> 2011-05-18 20:31 -> 8.16 5.93 5.16 1/247 3286
> 2011-05-18 20:32 -> 8.30 6.34 5.34 2/242 3302
> 2011-05-18 20:33 -> 5.72 5.95 5.27 1/242 3303
> 2011-05-18 20:34 -> 3.55 5.33 5.10 2/240 3313
> 2011-05-18 20:35 -> 3.39 4.93 4.98 1/241 3322
> 2011-05-18 20:36 -> 3.59 4.69 4.89 1/242 3323
> 2011-05-18 20:37 -> 2.67 4.24 4.72 1/242 3335
> 2011-05-18 20:38 -> 3.42 4.18 4.67 1/241 3338
> 2011-05-18 20:39 -> 2.92 3.91 4.55 2/241 3346
> 2011-05-18 20:40 -> 3.23 3.80 4.47 1/242 3351
> 2011-05-18 20:41 -> 4.63 4.12 4.54 1/240 3361
> 2011-05-18 20:42 -> 5.07 4.33 4.59 1/242 3370
> 2011-05-18 20:43 -> 4.46 4.31 4.57 1/241 3376
> 2011-05-18 20:44 -> 5.27 4.52 4.62 2/246 3382
> 2011-05-18 20:45 -> 4.89 4.56 4.63 1/240 3396
> 2011-05-18 20:46 -> 4.83 4.55 4.62 2/242 3406
> 2011-05-18 20:47 -> 4.75 4.58 4.62 1/243 3410
> 2011-05-18 20:48 -> 5.25 4.75 4.68 1/243 3417
> 2011-05-18 20:49 -> 4.40 4.65 4.65 9/243 3429
> 2011-05-18 20:50 -> 5.32 4.87 4.73 3/242 3437
> 2011-05-18 20:51 -> 5.48 4.99 4.78 1/243 3443
> 2011-05-18 20:52 -> 5.81 5.24 4.88 2/244 3457
> 2011-05-18 20:53 -> 5.37 5.24 4.90 1/245 3464
> 2011-05-18 20:54 -> 7.99 5.93 5.16 1/252 3478
> 2011-05-18 20:55 -> 7.36 6.24 5.32 1/245 3488
> 2011-05-18 20:56 -> 5.82 6.04 5.31 1/245 3500
> 2011-05-18 20:57 -> 5.21 5.83 5.28 1/246 3505
> 2011-05-18 20:58 -> 4.93 5.67 5.27 1/242 3505
> 2011-05-18 20:59 -> 5.36 5.74 5.32 1/240 3521
> 2011-05-18 21:00 -> 4.47 5.30 5.19 1/250 3537
> 2011-05-18 21:01 -> 7.26 6.10 5.48 2/244 3546
> 2011-05-18 21:02 -> 8.85 6.61 5.69 3/252 3566
> 2011-05-18 21:03 -> 7.53 6.64 5.76 1/243 3573
> 2011-05-18 21:04 -> 5.49 6.27 5.69 2/240 3584
> 2011-05-18 21:05 -> 6.65 6.40 5.77 1/243 3595
> 2011-05-18 21:06 -> 5.56 6.12 5.71 2/244 3600
> 2011-05-18 21:07 -> 6.28 6.23 5.78 3/242 3612
> 2011-05-18 21:08 -> 5.31 5.90 5.69 2/242 3625
> 2011-05-18 21:09 -> 5.84 5.98 5.73 2/244 3633
> 2011-05-18 21:10 -> 6.69 6.27 5.85 4/244 3648
> 2011-05-18 21:11 -> 9.35 6.96 6.10 1/246 3662
> 2011-05-18 21:12 -> 7.45 6.78 6.09 1/244 3671
> 2011-05-18 21:13 -> 8.69 7.14 6.25 1/251 3707
> 2011-05-18 21:14 -> 10.05 7.68 6.48 1/251 3732
> 
> here I received an email notification that the loadavg exceeded 10
> 
> 
> 2011-05-18 21:15 -> 6.69 7.16 6.38 1/248 3748
> 2011-05-18 21:16 -> 7.44 7.26 6.46 1/252 3762
> 2011-05-18 21:17 -> 8.09 7.67 6.67 1/244 3777
> 2011-05-18 21:18 -> 9.36 8.05 6.86 1/248 3808
> 2011-05-18 21:19 -> 6.53 7.48 6.74 2/246 3821
> 2011-05-18 21:20 -> 9.34 8.11 7.00 1/243 3848
> 2011-05-18 21:21 -> 7.57 7.73 6.93 1/245 3861
> 2011-05-18 21:22 -> 6.52 7.47 6.90 1/248 3883
> 2011-05-18 21:23 -> 8.71 7.82 7.05 3/254 3901
> 2011-05-18 21:24 -> 9.72 8.21 7.23 2/253 3918
> 2011-05-18 21:25 -> 9.95 8.46 7.37 1/252 3929
> 2011-05-18 21:26 -> 10.77 8.81 7.55 1/253 3939
> 2011-05-18 21:27 -> 10.62 9.08 7.72 1/253 3967
> 2011-05-18 21:28 -> 8.49 8.71 7.67 1/251 3985
> 2011-05-18 21:29 -> 9.76 8.89 7.79 12/256 3999
> 2011-05-18 21:30 -> 10.17 9.44 8.07 1/244 4012
> 2011-05-18 21:31 -> 8.35 8.96 7.98 1/255 4039
> 2011-05-18 21:32 -> 8.95 9.20 8.14 2/245 4045
> 2011-05-18 21:33 -> 8.63 9.20 8.21 1/244 4053
> 2011-05-18 21:34 -> 8.72 9.24 8.29 1/248 4075
> 2011-05-18 21:35 -> 10.09 9.48 8.43 1/253 4124
> 2011-05-18 21:36 -> 12.77 10.16 8.72 1/257 4170
> 2011-05-18 21:37 -> 8.47 9.39 8.55 1/251 4198
> 2011-05-18 21:38 -> 8.81 9.35 8.59 1/252 4211
> 2011-05-18 21:39 -> 8.14 9.09 8.55 2/246 4240
> 2011-05-18 21:40 -> 13.65 10.34 9.00 1/256 4276
> 2011-05-18 21:41 -> 9.54 9.66 8.85 2/252 4335
> 2011-05-18 21:42 -> 13.92 10.82 9.29 1/253 4369
> 2011-05-18 21:43 -> 9.13 10.16 9.17 1/241 4389
> 2011-05-18 21:44 -> 9.47 9.91 9.14 1/249 4431
> 2011-05-18 21:45 -> 10.61 10.07 9.24 1/257 4451
> 2011-05-18 21:46 -> 11.34 10.56 9.47 1/244 4456
> 
> Here I killed -stop the 4 rsync process
> 
> 2011-05-18 21:47 -> 5.10 8.96 8.99 1/234 4456
> 2011-05-18 21:48 -> 1.94 7.35 8.44 2/243 4484
> 
> Here I killed -cont the 4 rsync process
> 
> 2011-05-18 21:49 -> 2.43 6.44 8.05 1/246 4488
> 2011-05-18 21:50 -> 3.50 6.01 7.80 1/246 4488
> 2011-05-18 21:51 -> 3.18 5.49 7.51 8/243 4498
> 2011-05-18 21:52 -> 3.50 5.15 7.27 1/244 4503
> 2011-05-18 21:53 -> 3.83 4.93 7.06 1/245 4504
> 2011-05-18 21:54 -> 3.02 4.52 6.79 1/243 4514
> 2011-05-18 21:55 -> 3.37 4.32 6.57 2/245 4520
> 2011-05-18 21:56 -> 3.51 4.17 6.38 2/245 4524
> 2011-05-18 21:57 -> 3.15 3.97 6.17 1/243 4542
> 2011-05-18 21:58 -> 3.67 3.96 6.03 2/244 4543
> 2011-05-18 21:59 -> 3.55 3.88 5.87 1/243 4558
> 2011-05-18 22:00 -> 2.88 3.60 5.65 1/244 4563
> 2011-05-18 22:01 -> 3.29 3.62 5.53 1/245 4568
> 2011-05-18 22:02 -> 3.53 3.63 5.42 3/247 4582
> 2011-05-18 22:03 -> 3.17 3.54 5.27 2/244 4592
> 2011-05-18 22:04 -> 3.27 3.45 5.13 1/246 4598
> 2011-05-18 22:05 -> 3.64 3.53 5.06 1/245 4601
> 2011-05-18 22:06 -> 2.68 3.28 4.88 2/244 4612
> 2011-05-18 22:07 -> 3.25 3.33 4.79 1/245 4614
> 2011-05-18 22:08 -> 3.95 3.51 4.76 1/246 4615
> 2011-05-18 22:09 -> 3.23 3.43 4.66 1/242 4624
> 2011-05-18 22:10 -> 3.08 3.34 4.55 1/245 4631
> 2011-05-18 22:11 -> 3.46 3.43 4.51 1/244 4643
> 2011-05-18 22:12 -> 3.90 3.55 4.48 1/243 4658
> 
> a "top" when at loadavg 10+ show something like 8 or 10
> kernel threads named btrfs-cache-*  all in "D" status.
> 
> I'm no expert at all but I think thoses kthreads
> lack a bit of priority to finish the job they have to
> do. I will let you judge on that.
> 
> I've seen that behavior with older kernels too (plain fedora-14)
> 
> It does not happen often, may be one time every few weeks.
> When it happen, the loadavg increase endlessly until all the
> rsync prosess finish. Then loadavg drop to zero.
> 
> 

Yeah so this is a crappy thing about btrfs, we need to cache free space, so we
have to run these threads to read the extent tree to put together the free space
cache.  You can get around this by moving to a new kernel and mounting with

-o space_cache

This will enable the space caching feature, so you will get those threads once,
but then every time after that it will be fast and you shouldn't see those
threads at all.  Its a disk format change, so you only have to mount -o
space_cache once and then it will be permament.  Thanks,

Josef