17

UPDATE: I'm no longer having this problem on 4.9.* Not sure when it was fixed.

Everyday after a full system backup, various programs are failing with read errors until I run echo 2 > /proc/sys/vm/drop_caches to free reclaimable slab objects.

For example, here's the output of sudo apt-get update after a backup.

$ sudo apt-get update
Hit http://ftp.ca.debian.org unstable InRelease
Hit http://ftp.ca.debian.org experimental InRelease                                                            
Ign http://dl.google.com stable InRelease                                                                      
Get:1 http://ftp.ca.debian.org unstable/contrib amd64 Packages/DiffIndex [7,819 B]               
Hit http://dl.google.com stable Release.gpg                                     
Hit http://ppa.launchpad.net wily InRelease                               
Get:2 http://ftp.ca.debian.org unstable/non-free amd64 Packages/DiffIndex [6,577 B]            
Hit http://dl.google.com stable Release                                         
Hit http://ppa.launchpad.net wily InRelease                                                      
Get:3 http://ftp.ca.debian.org unstable/main amd64 Packages/DiffIndex [7,876 B]
Get:4 http://ftp.ca.debian.org unstable/contrib i386 Packages/DiffIndex [7,819 B]
Get:5 http://ppa.launchpad.net wily/main amd64 Packages [4,559 B]
Get:6 http://ftp.ca.debian.org unstable/non-free i386 Packages/DiffIndex [6,715 B]           
Get:7 http://ppa.launchpad.net wily/main i386 Packages [4,608 B]                                       
Get:8 http://ftp.ca.debian.org unstable/main i386 Packages/DiffIndex [7,876 B]                                 
Hit http://dl.google.com stable/main amd64 Packages                                             
Get:9 http://ftp.ca.debian.org unstable/contrib Translation-en/DiffIndex [2,161 B]             
Get:10 http://ppa.launchpad.net wily/main Translation-en [1,663 B]
Hit http://dl.google.com stable/main i386 Packages
E: Read error - read (5: Input/output error)    

Another sample error, this time with gulp/node.js

$ gulp watch
fs.js:651
  var r = binding.read(fd, buffer, offset, length, position);
                  ^

Error: EIO: i/o error, read
    at Error (native)
    at Object.fs.readSync (fs.js:651:19)
    at Object.fs.readFileSync (fs.js:467:24)
    at Object.Module._extensions..js (module.js:431:20)
    at Module.load (module.js:356:32)
    at Function.Module._load (module.js:313:12)
    at Module.require (module.js:366:17)
    at require (module.js:385:17)
    at Object.<anonymous> (/usr/local/lib/node_modules/gulp/node_modules/liftoff/node_modules/findup-sync/lib/findup-sync.js:15:12)
    at Module._compile (module.js:425:26)

Other programs fail with read errors as well, it's not just apt-get and gulp/node.js.

slabtop output:

$ sudo slabtop -o
 Active / Total Objects (% used)    : 7244650 / 7322302 (98.9%)
 Active / Total Slabs (% used)      : 882626 / 882697 (100.0%)
 Active / Total Caches (% used)     : 78 / 122 (63.9%)
 Active / Total Size (% used)       : 3423174.16K / 3434416.86K (99.7%)
 Minimum / Average / Maximum Object : 0.02K / 0.47K / 4096.00K

  OBJS ACTIVE  USE OBJ SIZE  SLABS OBJ/SLAB CACHE SIZE NAME                   
2419584 2418888  99%    0.97K 604896        4   2419584K btrfs_inode            
2249163 2249125  99%    0.19K 107103       21    428412K dentry                 
1271127 1270067  99%    0.30K  97779       13    391116K btrfs_delayed_node     
306243 299649  97%    0.06K   4861       63     19444K kmalloc-64             
241556 230494  95%    0.27K  17254       14     69016K btrfs_extent_buffer    
215068 212777  98%    0.14K   7681       28     30724K btrfs_path             
186102 185989  99%    0.56K  26586        7    106344K radix_tree_node        
174650 144422  82%    0.08K   3493       50     13972K btrfs_extent_state     
 37170  34869  93%    0.06K    590       63      2360K btrfs_free_space       
 37149  33473  90%    0.19K   1769       21      7076K kmalloc-192            
 32891  32382  98%    0.12K   1061       31      4244K kmalloc-96             
 26536  19327  72%    0.03K    214      124       856K kmalloc-32             
 24123  24015  99%    0.12K    731       33      2924K kernfs_node_cache      
 19656  19631  99%    0.07K    351       56      1404K Acpi-ParseExt          
 13728  11523  83%    0.25K    858       16      3432K kmalloc-256            
 11648  10783  92%    0.55K   1664        7      6656K inode_cache            
 11160   7283  65%    0.12K    360       31      1440K kmalloc-node           
 10696   9398  87%    0.07K    191       56       764K anon_vma               
  7059   6714  95%    0.10K    181       39       724K blkdev_ioc             
  3735   3615  96%    0.05K     45       83       180K ftrace_event_field     
  3696   3574  96%    0.50K    462        8      1848K kmalloc-512            
  3018   2871  95%    0.60K    503        6      2012K proc_inode_cache       
  1584   1503  94%    0.04K     16       99        64K Acpi-Namespace         
  1464   1418  96%    0.63K    244        6       976K shmem_inode_cache      
  1426   1348  94%    0.09K     31       46       124K trace_event_file       
  1400   1382  98%    1.00K    350        4      1400K kmalloc-1024           
  1311   1248  95%    4.00K   1311        1      5244K kmalloc-4096           
  1074    985  91%    0.62K    179        6       716K sock_inode_cache       
   852    806  94%    0.88K    213        4       852K RAW                    
   726    718  98%    2.94K    363        2      2904K task_struct            
   612    608  99%    2.00K    306        2      1224K kmalloc-2048           
   462    447  96%    2.05K    154        3      1232K idr_layer_cache        
   462    210  45%    0.18K     21       22        84K btrfs_trans_handle     
   429    157  36%    0.10K     11       39        44K buffer_head            
   384    181  47%    0.31K     32       12       128K bio-1                  
   355    217  61%    0.05K      5       71        20K file_lock_ctx          
   350    307  87%    1.12K     50        7       400K signal_cache           
   327    307  93%    2.06K    109        3       872K sighand_cache          
   289    211  73%    0.23K     17       17        68K cfq_queue              
   280    156  55%    0.38K     28       10       112K mnt_cache              

free output:

$ sudo free -h
              total        used        free      shared  buff/cache   available
Mem:            15G        2.3G        292M         28M         13G         13G
Swap:          7.5G        4.9M        7.4G

After running echo 2 > /proc/sys/vm/drop_caches the errors no longer appear. apt-get and other programs run fine.

slabtop output:

$ sudo slabtop -o
 Active / Total Objects (% used)    : 586239 / 777567 (75.4%)
 Active / Total Slabs (% used)      : 57059 / 57123 (99.9%)
 Active / Total Caches (% used)     : 79 / 122 (64.8%)
 Active / Total Size (% used)       : 180630.05K / 229256.91K (78.8%)
 Minimum / Average / Maximum Object : 0.02K / 0.29K / 4096.00K

  OBJS ACTIVE  USE OBJ SIZE  SLABS OBJ/SLAB CACHE SIZE NAME                   
241556 230586  95%    0.27K  17254       14     69016K btrfs_extent_buffer    
146251 100390  68%    0.56K  20893        7     83572K radix_tree_node        
 50967  26035  51%    0.06K    809       63      3236K kmalloc-64             
 37170  34866  93%    0.06K    590       63      2360K btrfs_free_space       
 37149  33440  90%    0.19K   1769       21      7076K kmalloc-192            
 37016   7054  19%    0.14K   1322       28      5288K btrfs_path             
 35889  13681  38%    0.19K   1709       21      6836K dentry                 
 27700   1805   6%    0.08K    554       50      2216K btrfs_extent_state     
 26412  19384  73%    0.03K    213      124       852K kmalloc-32             
 24123  24067  99%    0.12K    731       33      2924K kernfs_node_cache      
 19656  19637  99%    0.07K    351       56      1404K Acpi-ParseExt          
 13712  11542  84%    0.25K    857       16      3428K kmalloc-256            
 12152   8791  72%    0.97K   3038        4     12152K btrfs_inode            
 10696   9414  88%    0.07K    191       56       764K anon_vma               
  9632   8948  92%    0.55K   1376        7      5504K inode_cache            
  8742   4845  55%    0.12K    282       31      1128K kmalloc-node           
  7059   6794  96%    0.10K    181       39       724K blkdev_ioc             
  4867   2606  53%    0.12K    157       31       628K kmalloc-96             
  3735   3710  99%    0.05K     45       83       180K ftrace_event_field     
  3688   3525  95%    0.50K    461        8      1844K kmalloc-512            
  1794    498  27%    0.30K    138       13       552K btrfs_delayed_node     
  1584   1521  96%    0.04K     16       99        64K Acpi-Namespace         
  1464   1418  96%    0.63K    244        6       976K shmem_inode_cache      
  1426   1348  94%    0.09K     31       46       124K trace_event_file       
  1420   1357  95%    1.00K    355        4      1420K kmalloc-1024           
  1310   1252  95%    4.00K   1310        1      5240K kmalloc-4096           
  1074   1016  94%    0.62K    179        6       716K sock_inode_cache       
   852    807  94%    0.88K    213        4       852K RAW                    
   726    713  98%    2.94K    363        2      2904K task_struct            
   648    254  39%    0.60K    108        6       432K proc_inode_cache       
   636    635  99%    2.00K    318        2      1272K kmalloc-2048           
   506    240  47%    0.18K     23       22        92K btrfs_trans_handle     
   468    190  40%    0.10K     12       39        48K buffer_head            
   462    447  96%    2.05K    154        3      1232K idr_layer_cache        
   408    250  61%    0.31K     34       12       136K bio-1                  
   355    161  45%    0.05K      5       71        20K file_lock_ctx          
   350    307  87%    1.12K     50        7       400K signal_cache           
   327    307  93%    2.06K    109        3       872K sighand_cache          
   300    286  95%    0.38K     30       10       120K mnt_cache              
   297     85  28%    0.04K      3       99        12K btrfs_delayed_extent_op

free output:

$ sudo free -h
              total        used        free      shared  buff/cache   available
Mem:            15G        2.3G        6.1G         28M        7.3G         13G
Swap:          7.5G        4.8M        7.4G

I'm running Debian Sid on a btrfs but I've had the same problem with ext4 so I don't think it's a filesystem specific issue.

$ uname -v
#1 SMP Debian 4.2.6-1 (2015-11-10)

I've also tried to set vfs_cache_pressure to a high value.

vm.vfs_cache_pressure=[ 100 | 1000 | 100000 ]

I get less read errors at 100000 but CPU usage climbs and system responsiveness becomes terrible so I'm looking for an alternate solution.

I could stick echo 2 > /proc/sys/vm/drop_caches into a cron job but that's not fixing the problem, it's just workaround.

Here's dmesg

  • Same think here. Having worked in Solaris previously, I just take for granted previously allocated caches are not returned to free memory to optimize/speed up memory allocation calls. However while that makes sense in a physical machine, it does not makes sense anymore in VM farms. – Rui F Ribeiro Nov 22 '15 at 14:27
  • 5
    That sounds like a bug. Slab objects stay around for a while — that's the point of a cache — but if something does need the resources then they should be reclaimed. – Gilles Nov 22 '15 at 23:44
  • Are there any error/bug messages in dmesg,messages log files? – VenkatC Nov 23 '15 at 1:25
  • No unusual errors before the backup. Pastebin link to my dmesg added. – Richard Ayotte Nov 23 '15 at 1:50
  • 1
    Holy schmokes, I just ran into today with npm run watch followup operations failed with that non-descript read error. Would've never thought of this on my own. drop_caches restored operations instantly, but what the heck is going on here? I'm on kernel 4.4.4. – lkraav Mar 24 '16 at 19:36
1

kernel/mm/slab.c have had a bunch of recent (jan, feb 2017) patches addressing, among other things, slow cache destruction; in certain cases the cache destruction operation could run for many hours. The operation itself was also performance expensive.

That said it is not unsual to see some high figures if you have a lot of disk I/O activity. Although, your counts were probably on the high side, and may have suffered from one of the addressed bugs concerning slow destruction.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.