{"action":"created","issue":{"url":"https://api.github.com/repos/zfsonlinux/zfs/issues/7922","repository_url":"https://api.github.com/repos/zfsonlinux/zfs","labels_url":"https://api.github.com/repos/zfsonlinux/zfs/issues/7922/labels{/name}","comments_url":"https://api.github.com/repos/zfsonlinux/zfs/issues/7922/comments","events_url":"https://api.github.com/repos/zfsonlinux/zfs/issues/7922/events","html_url":"https://github.com/zfsonlinux/zfs/issues/7922","id":361034736,"node_id":"MDU6SXNzdWUzNjEwMzQ3MzY=","number":7922,"title":"High CPU usage of dbuf_evict for small random I/O","user":{"login":"cvoltz","id":549284,"node_id":"MDQ6VXNlcjU0OTI4NA==","avatar_url":"https://avatars0.githubusercontent.com/u/549284?v=4","gravatar_id":"","url":"https://api.github.com/users/cvoltz","html_url":"https://github.com/cvoltz","followers_url":"https://api.github.com/users/cvoltz/followers","following_url":"https://api.github.com/users/cvoltz/following{/other_user}","gists_url":"https://api.github.com/users/cvoltz/gists{/gist_id}","starred_url":"https://api.github.com/users/cvoltz/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/cvoltz/subscriptions","organizations_url":"https://api.github.com/users/cvoltz/orgs","repos_url":"https://api.github.com/users/cvoltz/repos","events_url":"https://api.github.com/users/cvoltz/events{/privacy}","received_events_url":"https://api.github.com/users/cvoltz/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":12,"created_at":"2018-09-17T20:39:33Z","updated_at":"2018-09-20T19:10:47Z","closed_at":null,"author_association":"CONTRIBUTOR","body":"### System information\r\nType | Version/Name\r\n --- | --- \r\nDistribution Name\t| CentOS\r\nDistribution Version\t| 7.5\r\nLinux Kernel\t| 3.10.0-862.11.6.el7.x86_64\r\nArchitecture\t| x86_64\r\nZFS Version\t| 0.7.11-1\r\nSPL Version\t| 0.7.11-1\r\n\r\n### Describe the problem you're observing\r\nPoor performance with low I/O utilization and high CPU usage. This may be similar to #6952 except the perf results are different and I'm using the latest release, which suggests a new bottleneck.\r\n\r\n### Describe how to reproduce the problem\r\n1. Create a pool named `backup` with multiple RAIDZ2 VDEVs\r\nIn my case, I have 4 VDEVs. 2 have 12 disks (each 2 TB) and the other 2 have 5 disks (each 4 TB) so the VDEVs are roughly equal in size.\r\n1. Create a dataset named `snapshots` in the `backup` pool\r\n1. Create a `.sync` directory within the dataset\r\n1. Enable dedup and compression on the `snapshots` dataset\r\n1. Fill the `.sync` directory with a bunch of small files in nested directories\r\nMy dataset has only 6.49 TB of data from the `/etc`, `/home`, `/opt`, `/usr/local`, `/var/lib`, `/var/log`, `/var/named`, and `/var/www` directories of several machines in 7,284,710 files in directories as deep as 35 levels.\r\n1. Run `cp -al /backup/snapshots/.sync /backup/snapshots/hourly.0`\r\nThis is what `rsnapshot` does when rolling over an interval (an hour in this case).\r\n\r\nSimilar poor performance can be seen by running:\r\n`find /backup/snapshots/.sync -type f -print | wc -l`\r\nor\r\n`find /backup/snapshots -type d | sed 's|[^/]||g' | sort | tail -n1`\r\nor\r\n`du -shc /backup/snapshots`\r\nAll take an excessively long time (more then an hour) to run.\r\n\r\n### Include any warning/errors/backtraces from the system logs\r\n`top`\r\n![screenshot from 2018-09-17 14-13-12](https://user-images.githubusercontent.com/549284/45644642-dad9f780-ba83-11e8-8b29-1133ebec4f22.png)\r\n\r\n`perf top -p 1498`:\r\n![screenshot from 2018-09-17 14-17-22](https://user-images.githubusercontent.com/549284/45644876-766b6800-ba84-11e8-869b-9edf4cf4c41f.png)\r\n\r\n```\r\n# zpool iostat 1 30\r\n              capacity     operations     bandwidth\r\npool        alloc   free   read  write   read  write\r\n----------  -----  -----  -----  -----  -----  -----\r\nbackup      6.49T  73.3T    237    708  1.36M  4.35M\r\nbackup      6.49T  73.3T    420      0  1.64M      0\r\nbackup      6.49T  73.3T    268      0  1.05M      0\r\nbackup      6.49T  73.3T    419      0  1.65M      0\r\nbackup      6.49T  73.3T    584      0  2.28M      0\r\nbackup      6.49T  73.3T    513  3.04K  2.01M  18.4M\r\nbackup      6.49T  73.3T    228      0   915K      0\r\nbackup      6.49T  73.3T    102      0   410K      0\r\nbackup      6.49T  73.3T    265      0  1.04M      0\r\nbackup      6.49T  73.3T    229      0   919K      0\r\nbackup      6.49T  73.3T    261  2.72K  1.02M  16.9M\r\nbackup      6.49T  73.3T    219      0   879K      0\r\nbackup      6.49T  73.3T    284      0  1.11M      0\r\nbackup      6.49T  73.3T    192      0   772K      0\r\nbackup      6.49T  73.3T    263  1.01K  1.04M  4.82M\r\nbackup      6.49T  73.3T     85  2.45K   342K  14.7M\r\nbackup      6.49T  73.3T    132      0   529K      0\r\nbackup      6.49T  73.3T    157      0   631K      0\r\nbackup      6.49T  73.3T    126      0   504K      0\r\nbackup      6.49T  73.3T     47    275   191K  1.08M\r\nbackup      6.49T  73.3T     59  1.95K   254K  11.3M\r\nbackup      6.49T  73.3T     52      0   211K      0\r\nbackup      6.49T  73.3T     40      0   163K      0\r\nbackup      6.49T  73.3T     45      0   183K      0\r\nbackup      6.49T  73.3T     38    561   155K  2.25M\r\nbackup      6.49T  73.3T     23    966  95.3K  3.96M\r\nbackup      6.49T  73.3T     40      0   163K      0\r\nbackup      6.49T  73.3T     53      0   215K      0\r\nbackup      6.49T  73.3T     37      0   151K      0\r\nbackup      6.49T  73.3T     31    136   127K   547K\r\n```\r\n\r\n```\r\n# zfs list\r\nNAME               USED  AVAIL  REFER  MOUNTPOINT\r\nbackup            6.54T  48.3T   230K  /backup\r\nbackup/log        63.4M  48.3T  63.4M  /backup/log\r\nbackup/snapshots  6.49T  48.3T  6.49T  /backup/snapshots\r\n```\r\n\r\n```\r\n# zpool get all backup\r\nNAME    PROPERTY                       VALUE                          SOURCE\r\nbackup  size                           79.8T                          -\r\nbackup  capacity                       8%                             -\r\nbackup  altroot                        -                              default\r\nbackup  health                         ONLINE                         -\r\nbackup  guid                           16460844651660370475           -\r\nbackup  version                        -                              default\r\nbackup  bootfs                         -                              default\r\nbackup  delegation                     on                             default\r\nbackup  autoreplace                    off                            default\r\nbackup  cachefile                      none                           local\r\nbackup  failmode                       wait                           default\r\nbackup  listsnapshots                  off                            default\r\nbackup  autoexpand                     off                            default\r\nbackup  dedupditto                     0                              default\r\nbackup  dedupratio                     1.56x                          -\r\nbackup  free                           73.3T                          -\r\nbackup  allocated                      6.49T                          -\r\nbackup  readonly                       off                            -\r\nbackup  ashift                         12                             local\r\nbackup  comment                        -                              default\r\nbackup  expandsize                     -                              -\r\nbackup  freeing                        0                              -\r\nbackup  fragmentation                  4%                             -\r\nbackup  leaked                         0                              -\r\nbackup  multihost                      off                            default\r\nbackup  feature@async_destroy          enabled                        local\r\nbackup  feature@empty_bpobj            active                         local\r\nbackup  feature@lz4_compress           active                         local\r\nbackup  feature@multi_vdev_crash_dump  enabled                        local\r\nbackup  feature@spacemap_histogram     active                         local\r\nbackup  feature@enabled_txg            active                         local\r\nbackup  feature@hole_birth             active                         local\r\nbackup  feature@extensible_dataset     active                         local\r\nbackup  feature@embedded_data          active                         local\r\nbackup  feature@bookmarks              enabled                        local\r\nbackup  feature@filesystem_limits      enabled                        local\r\nbackup  feature@large_blocks           enabled                        local\r\nbackup  feature@large_dnode            active                         local\r\nbackup  feature@sha512                 enabled                        local\r\nbackup  feature@skein                  enabled                        local\r\nbackup  feature@edonr                  enabled                        local\r\nbackup  feature@userobj_accounting     active                         local\r\n```\r\n\r\n```\r\n# zfs get all backup/snapshots\r\nNAME              PROPERTY              VALUE                  SOURCE\r\nbackup/snapshots  type                  filesystem             -\r\nbackup/snapshots  creation              Sat Sep 15 15:35 2018  -\r\nbackup/snapshots  used                  6.49T                  -\r\nbackup/snapshots  available             48.3T                  -\r\nbackup/snapshots  referenced            6.49T                  -\r\nbackup/snapshots  compressratio         1.06x                  -\r\nbackup/snapshots  mounted               yes                    -\r\nbackup/snapshots  quota                 none                   default\r\nbackup/snapshots  reservation           none                   default\r\nbackup/snapshots  recordsize            128K                   default\r\nbackup/snapshots  mountpoint            /backup/snapshots      default\r\nbackup/snapshots  sharenfs              off                    default\r\nbackup/snapshots  checksum              on                     default\r\nbackup/snapshots  compression           on                     local\r\nbackup/snapshots  atime                 on                     default\r\nbackup/snapshots  devices               on                     default\r\nbackup/snapshots  exec                  on                     default\r\nbackup/snapshots  setuid                on                     default\r\nbackup/snapshots  readonly              off                    default\r\nbackup/snapshots  zoned                 off                    default\r\nbackup/snapshots  snapdir               hidden                 default\r\nbackup/snapshots  aclinherit            restricted             default\r\nbackup/snapshots  createtxg             24                     -\r\nbackup/snapshots  canmount              on                     default\r\nbackup/snapshots  xattr                 on                     default\r\nbackup/snapshots  copies                1                      default\r\nbackup/snapshots  version               5                      -\r\nbackup/snapshots  utf8only              off                    -\r\nbackup/snapshots  normalization         none                   -\r\nbackup/snapshots  casesensitivity       sensitive              -\r\nbackup/snapshots  vscan                 off                    default\r\nbackup/snapshots  nbmand                off                    default\r\nbackup/snapshots  sharesmb              off                    default\r\nbackup/snapshots  refquota              none                   default\r\nbackup/snapshots  refreservation        none                   default\r\nbackup/snapshots  guid                  7864697502022885929    -\r\nbackup/snapshots  primarycache          all                    default\r\nbackup/snapshots  secondarycache        all                    default\r\nbackup/snapshots  usedbysnapshots       0B                     -\r\nbackup/snapshots  usedbydataset         6.49T                  -\r\nbackup/snapshots  usedbychildren        0B                     -\r\nbackup/snapshots  usedbyrefreservation  0B                     -\r\nbackup/snapshots  logbias               latency                default\r\nbackup/snapshots  dedup                 on                     local\r\nbackup/snapshots  mlslabel              none                   default\r\nbackup/snapshots  sync                  standard               default\r\nbackup/snapshots  dnodesize             legacy                 default\r\nbackup/snapshots  refcompressratio      1.06x                  -\r\nbackup/snapshots  written               6.49T                  -\r\nbackup/snapshots  logicalused           6.73T                  -\r\nbackup/snapshots  logicalreferenced     6.73T                  -\r\nbackup/snapshots  volmode               default                default\r\nbackup/snapshots  filesystem_limit      none                   default\r\nbackup/snapshots  snapshot_limit        none                   default\r\nbackup/snapshots  filesystem_count      none                   default\r\nbackup/snapshots  snapshot_count        none                   default\r\nbackup/snapshots  snapdev               hidden                 default\r\nbackup/snapshots  acltype               off                    default\r\nbackup/snapshots  context               none                   default\r\nbackup/snapshots  fscontext             none                   default\r\nbackup/snapshots  defcontext            none                   default\r\nbackup/snapshots  rootcontext           none                   default\r\nbackup/snapshots  relatime              off                    default\r\nbackup/snapshots  redundant_metadata    all                    default\r\nbackup/snapshots  overlay               off                    default\r\n```"},"comment":{"url":"https://api.github.com/repos/zfsonlinux/zfs/issues/comments/423299117","html_url":"https://github.com/zfsonlinux/zfs/issues/7922#issuecomment-423299117","issue_url":"https://api.github.com/repos/zfsonlinux/zfs/issues/7922","id":423299117,"node_id":"MDEyOklzc3VlQ29tbWVudDQyMzI5OTExNw==","user":{"login":"cvoltz","id":549284,"node_id":"MDQ6VXNlcjU0OTI4NA==","avatar_url":"https://avatars0.githubusercontent.com/u/549284?v=4","gravatar_id":"","url":"https://api.github.com/users/cvoltz","html_url":"https://github.com/cvoltz","followers_url":"https://api.github.com/users/cvoltz/followers","following_url":"https://api.github.com/users/cvoltz/following{/other_user}","gists_url":"https://api.github.com/users/cvoltz/gists{/gist_id}","starred_url":"https://api.github.com/users/cvoltz/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/cvoltz/subscriptions","organizations_url":"https://api.github.com/users/cvoltz/orgs","repos_url":"https://api.github.com/users/cvoltz/repos","events_url":"https://api.github.com/users/cvoltz/events{/privacy}","received_events_url":"https://api.github.com/users/cvoltz/received_events","type":"User","site_admin":false},"created_at":"2018-09-20T19:10:47Z","updated_at":"2018-09-20T19:10:47Z","author_association":"CONTRIBUTOR","body":"@GregorKopka I definitely see the ARC target size changing on the system when running just `rsync` on a the dataset without deduplication, despite memory being available:\r\n```\r\n# free -g\r\n              total        used        free      shared  buff/cache   available\r\nMem:            125          67          24           0          33          24\r\nSwap:             7           0           7\r\n```\r\n\r\n```\r\n# arcstat.py  1\r\n    time  read  miss  miss%  dmis  dm%  pmis  pm%  mmis  mm%  arcsz     c\r\n11:30:51   35K  3.5K      9  3.3K    9   249   32  3.0K    8   1.1G   94G\r\n...\r\n13:28:09  1.2K    18      1    18    1     0    0    18    1    93G   93G\r\n...\r\n13:28:15  1.3K    54      4    54    4     0    0    54    4    90G   90G\r\n...\r\n13:28:29  1.8K    97      5    97    5     0    0    97    5    91G   91G\r\n...\r\n13:28:40  1.4K    87      6    87    6     0    0    87    6    92G   92G\r\n...\r\n13:29:00  2.0K    66      3    66    3     0    0    66    3    90G   90G\r\n13:29:01   973    48      4    48    4     0    0    48    4    90G   90G\r\n13:29:02  2.0K    51      2    51    2     0    0    51    2    89G   89G\r\n...\r\n13:29:06  2.0K    90      4    90    4     0    0    90    4    89G   90G\r\n...\r\n13:29:18  1.9K     0      0     0    0     0    0     0    0    91G   91G\r\n...\r\n13:29:38  2.0K    25      1    25    1     0    0    25    1    88G   88G\r\n...\r\n13:51:59   39K  6.6K     16  6.6K   16     0    0  6.6K   16    84G   84G\r\n```\r\nI tried running your modified `arcstat.py` as you requested but using just the load from `rsync`. You can see the ARC target size changing but the new parameters don't (and it looks like you need to fix a bug in your alignment):\r\n```\r\n# ./arcstat.py -f time,read,miss,miss%,dread,dmis,dm%,pread,pmis,pm%,mread,mmis,mm%,arcsz,c,mfu,mru,mfug,mrug,eskip,mtxmis,grow,free,need 1 30\r\n    time  read  miss  miss%  dread  dmis  dm%  pread  pmis  pm%  mread  mmis  mm%  arcsz     c   mfu   mru  mfug  mrug  eskip  mtxmis  grow  free  need\r\n14:04:41    24     0      0     24     0    0      0     0    0    24     0    0    81G   82G    24     0     0     0      0       0  0  2.0G     0\r\n14:04:42  1.7K    46      2   1.7K    46    2      0     0    0  1.7K    46    2    82G   82G  1.2K   454     0     0      0       0  0  2.0G     0\r\n14:04:43  1.9K    22      1   1.9K    22    1      0     0    0  1.9K    22    1    82G   82G  1.7K   201     0     0      0       0  0  2.0G     0\r\n14:04:44  1.3K    14      1   1.3K    14    1      0     0    0  1.3K    14    1    82G   82G   916   406     0     0      0       0  0  2.0G     0\r\n14:04:45  2.0K    26      1   2.0K    26    1      0     0    0  2.0K    26    1    82G   82G  1.2K   763     0     0      0       0  0  2.0G     0\r\n14:04:46  1.7K     0      0   1.7K     0    0      0     0    0  1.7K     0    0    82G   82G  1.1K   606     0     0      0       0  0  2.0G     0\r\n14:04:47  1.7K    22      1   1.7K    22    1      0     0    0  1.7K    22    1    82G   82G  1.4K   292     0     0      0       0  0  2.0G     0\r\n14:04:48  1.8K     0      0   1.8K     0    0      0     0    0  1.8K     0    0    82G   82G  1.1K   664     0     0      0       0  0  2.0G     0\r\n14:04:49  2.0K    22      1   2.0K    22    1      0     0    0  2.0K    22    1    82G   82G  1.4K   608     0     0      0       0  0  2.0G     0\r\n14:04:50  1.6K     0      0   1.6K     0    0      0     0    0  1.6K     0    0    82G   83G  1.2K   392     0     0      0       0  0  2.0G     0\r\n14:04:51  1.9K    22      1   1.9K    22    1      0     0    0  1.9K    22    1    83G   83G  1.1K   736     0     0      0       0  0  2.0G     0\r\n14:04:52  1.5K     0      0   1.5K     0    0      0     0    0  1.5K     0    0    83G   83G  1.2K   298     0     0      0       0  0  2.0G     0\r\n14:04:53  1.7K     0      0   1.7K     0    0      0     0    0  1.7K     0    0    83G   83G  1.1K   612     0     0      0       0  0  2.0G     0\r\n14:04:54  1.9K    26      1   1.9K    26    1      0     0    0  1.9K    26    1    83G   83G  1.4K   400     0     0      0       0  0  2.0G     0\r\n14:04:55  1.5K     1      0   1.5K     1    0      0     0    0  1.5K     1    0    83G   83G  1.2K   289     0     0      0       0  0  2.0G     0\r\n14:04:56  2.0K    22      1   2.0K    22    1      0     0    0  2.0K    22    1    83G   83G  1.5K   486     0     0      0       0  0  2.0G     0\r\n14:04:57  1.4K     0      0   1.4K     0    0      0     0    0  1.4K     0    0    83G   83G   831   618     0     0      0       0  0  2.0G     0\r\n14:04:58  1.8K    22      1   1.8K    22    1      0     0    0  1.8K    22    1    83G   83G  1.5K   324     0     0      0       0  0  2.0G     0\r\n14:04:59  1.8K     0      0   1.8K     0    0      0     0    0  1.8K     0    0    83G   83G  1.4K   484     0     0      0       0  0  2.0G     0\r\n14:05:00  2.3K    22      0   2.3K    22    0      0     0    0  2.3K    22    0    84G   84G  1.9K   400     0     0      0       0  0  2.0G     0\r\n14:05:01  1.8K    15      0   1.8K    15    0      0     0    0  1.8K    15    0    84G   84G  1.6K   242     0     0      0       0  0  2.0G     0\r\n14:05:02  1.7K    22      1   1.7K    22    1      0     0    0  1.7K    22    1    84G   84G  1.3K   447     0     0      0       0  0  2.0G     0\r\n14:05:03  2.0K    41      2   2.0K    41    2      0     0    0  2.0K    41    2    84G   84G  1.6K   348     0     0      0       0  0  2.0G     0\r\n14:05:04  2.1K    28      1   2.1K    28    1      0     0    0  2.1K    28    1    84G   84G  1.7K   406     0     0      0       0  0  2.0G     0\r\n14:05:05  1.9K     1      0   1.9K     1    0      0     0    0  1.9K     1    0    84G   84G  1.5K   400     1     0      0       0  0  2.0G     0\r\n14:05:06  1.8K    23      1   1.8K    23    1      0     0    0  1.8K    23    1    84G   84G  1.3K   462     1     0      0       0  0  2.0G     0\r\n14:05:07  1.8K     0      0   1.8K     0    0      0     0    0  1.8K     0    0    84G   84G  1.6K   201     0     0      0       1  0  2.0G     0\r\n14:05:08  2.1K    22      1   2.1K    22    1      0     0    0  2.1K    22    1    84G   84G  1.7K   403     0     0      0       0  0  2.0G     0\r\n14:05:09  2.1K     0      0   2.1K     0    0      0     0    0  2.1K     0    0    84G   84G  1.3K   835     0     0      0       0  0  2.0G     0\r\n14:05:10  1.9K    22      1   1.9K    22    1      0     0    0  1.9K    22    1    84G   84G  1.4K   484     0     0      0       0  0  2.0G     0\r\n```"}}
{"actor":{"display_login":"cvoltz"}}