** Summary changed:
- Issue with bcache bch_mca_scan causing huge IO wait
+ bcache: Issues with large IO wait in bch_mca_scan() when shrinker is enabled
** Also affects: linux (Ubuntu Focal)
Importance: Undecided
Status: New
** Changed in: linux (Ubuntu)
Status: Confirmed => Fix Released
** Changed in: linux (Ubuntu Bionic)
Status: New => In Progress
** Changed in: linux (Ubuntu Focal)
Status: New => In Progress
** Changed in: linux (Ubuntu Bionic)
Importance: Undecided => Medium
** Changed in: linux (Ubuntu Focal)
Importance: Undecided => Medium
** Changed in: linux (Ubuntu Bionic)
Assignee: (unassigned) => Matthew Ruffell (mruffell)
** Changed in: linux (Ubuntu Focal)
Assignee: (unassigned) => Matthew Ruffell (mruffell)
** Description changed:
- Hello,
+ BugLink: https://bugs.launchpad.net/bugs/1898786
- In short, we faced an issue with a huge IO wait on a bionic Ubuntu
4.15.0-118.119-generic kernel.
- This is the full list of process and the kernel function they were stuck in
[0].
+ [Impact]
- The main issue can probably be summarized by this perf reports
- * first identify that the cpu are stuck in idle because of something[1]
- * second, see what kernel function seems to stuck the process kswapd0 and
kswapd1 [2].
-
- We could see that this seems to be the mutex_lock in the bch_mca_scan
- function [3].
-
- After running the command:
-
- | sudo bash -c "echo 1 > /sys/fs/bcache/f1a1e8cb-3e6b-40ea-852e-
- 583c48d0c2b8/internal/btree_shrinker_disabled"
-
- The server started to respond normally and the IO wait dropped
- significantly
-
- Here is a trace of the bcache event related lock in the kernel obtained
- with some bpfcc-tools [4].
-
- klockstat-bpfcc -c bch_ -i 5 -s 3
-
- The trace has been run in parallel with the following command line
-
- echo "Shrinker disabled: $(date)"; sleep 60; echo "Enabling shrinker:
- $(date)"; echo 0 | sudo tee
- /sys/block/bcache0/bcache/cache/internal/btree_shrinker_disabled ; sleep
- 60; echo "Disabling shrinker: $(date)"; echo 1 | sudo tee
- /sys/block/bcache0/bcache/cache/internal/btree_shrinker_disabled; sleep
- 60; echo "End of test: $(date)"
-
- Trying to dig more, we reduced by 20 GB the memory allocated to a VM on the
server.
- * The bcache btree size fluctuation seems "normal" [5]
- * I noticed that, when the shrinker was enabled,a lot of time was spent in
the locks during "bch_btree_insert_node". [6]
-
- I decided to check if one of the function called during
- bch_btree_insert_node was taking longer than usual when the shrinker was
+ Systems that utilise bcache can experience extremely high IO wait times
+ when under constant IO pressure. The IO wait times seem to stay at a
+ consistent 1 second, and never drop as long as the bcache shrinker is
enabled.
- I finally found the "funclatency" tool and tried do have the same approach I
had with the klockstat [7]. However, that was inconclusive. I could see there
that the bch_btree_insert_node was barely called during the whole duration of
the test.
- Which made me think it's amount of time spent in lock is more due to another
process acquiring the lock.
+ If you disable the shrinker, then IO wait drops significantly to normal
+ levels.
- I'm going to try to have another go with some perf/klockstat/funclatency
- focused on bch_mca_scan and the function called there.
+ We did some perf analysis, and it seems we spend a huge amount of time
+ in bch_mca_scan(), likely waiting for the mutex "&c->bucket_lock".
- Also, here are some memory related metrics [8].
+ Looking at the recent commits in Bionic, we found the following commit
+ merged in upstream 5.1-rc1 and backported to 4.15.0-87-generic through
+ upstream stable:
- Now another perf stacktrace with the command used [9].
- Strangely this one doesn't show any bch_mca_scan at all.
+ commit 9fcc34b1a6dd4b8e5337e2b6ef45e428897eca6b
+ Author: Coly Li <col...@suse.de>
+ Date: Wed Nov 13 16:03:24 2019 +0800
+ Subject: bcache: at least try to shrink 1 node in bch_mca_scan()
+ Link:
https://github.com/torvalds/linux/commit/9fcc34b1a6dd4b8e5337e2b6ef45e428897eca6b
- I enabled the shrinker again, hoping to get more traces, but apparently the
timeframe was not right. Not enough load to trigger the cliff resulting in a
1sec IOwait plateau.
- Which is interesting because that means that without the maximal workload,
the kernel can cope with the shrinker.
+ It mentions in the description that:
- [0]: https://pastebin.ubuntu.com/p/QYXPdsMCWC/
- [1]: https://pastebin.ubuntu.com/p/BFsvF7H54r/
- [2]: https://pastebin.ubuntu.com/p/35qdsHYHf5/
- [3]:
https://git.launchpad.net/~ubuntu-kernel/ubuntu/+source/linux/+git/bionic/tree/drivers/md/bcache/btree.c?h=Ubuntu-4.15.0-118.119#n674
- [4]: https://pastebin.ubuntu.com/p/qhyqP35fCw/
- [5]: https://pastebin.ubuntu.com/p/McjxxqTVjn/
- [6]: https://pastebin.ubuntu.com/p/KmrnW4Ng8F/
- [7]: https://pastebin.ubuntu.com/p/fSX4c7tTFV/
- [8]: https://pastebin.ubuntu.com/p/CZgXkgKhmJ/
- [9]: https://pastebin.ubuntu.com/p/DzKCP8NGdf/
+ > If sc->nr_to_scan is smaller than c->btree_pages, after the above
+ > calculation, variable 'nr' will be 0 and nothing will be shrunk. It is
+ > frequeently observed that only 1 or 2 is set to sc->nr_to_scan and make
+ > nr to be zero. Then bch_mca_scan() will do nothing more then acquiring
+ > and releasing mutex c->bucket_lock.
- ====================
- $ cat /proc/version_signature
- Ubuntu 4.15.0-118.119-generic 4.15.18
+ This seems to be what is going on here, but the above commit only
+ addresses when nr is 0.
- ProblemType: Bug
- DistroRelease: Ubuntu 18.04
- Package: linux-image-4.15.0-118-generic 4.15.0-118.119
- ProcVersionSignature: User Name 4.15.0-118.119-generic 4.15.18
- Uname: Linux 4.15.0-118-generic x86_64
- AlsaDevices:
- total 0
- crw-rw---- 1 root audio 116, 1 Sep 29 10:04 seq
- crw-rw---- 1 root audio 116, 33 Sep 29 10:04 timer
- AplayDevices: Error: [Errno 2] No such file or directory: 'aplay': 'aplay'
- ApportVersion: 2.20.9-0ubuntu7.16
- Architecture: amd64
- ArecordDevices: Error: [Errno 2] No such file or directory: 'arecord':
'arecord'
- AudioDevicesInUse: Error: command ['fuser', '-v', '/dev/snd/seq',
'/dev/snd/timer'] failed with exit code 1:
- Date: Tue Oct 6 20:36:18 2020
- IwConfig: Error: [Errno 2] No such file or directory: 'iwconfig': 'iwconfig'
- MachineType: HP ProLiant DL380 G7
- PciMultimedia:
+ From what I can see, the problems we are experiencing are when nr is 1
+ or 2, and again, we just waste time in bch_mca_scan() waiting on
+ c->bucket_lock, only to release c->bucket_lock since the shrinker loop
+ never executes since there is no work to do.
- ProcFB: 0 radeondrmfb
- ProcKernelCmdLine: BOOT_IMAGE=/boot/vmlinuz-4.15.0-118-generic
root=UUID=c6ad1629-a506-4043-a339-6d57f0708d12 ro console=ttyS1,115200 nosplash
- RelatedPackageVersions:
- linux-restricted-modules-4.15.0-118-generic N/A
- linux-backports-modules-4.15.0-118-generic N/A
- linux-firmware 1.173.18
- RfKill: Error: [Errno 2] No such file or directory: 'rfkill': 'rfkill'
- SourcePackage: linux
- UpgradeStatus: Upgraded to bionic on 2019-09-27 (375 days ago)
- dmi.bios.date: 05/05/2011
- dmi.bios.vendor: HP
- dmi.bios.version: P67
- dmi.chassis.type: 23
- dmi.chassis.vendor: HP
- dmi.modalias:
dmi:bvnHP:bvrP67:bd05/05/2011:svnHP:pnProLiantDL380G7:pvr:cvnHP:ct23:cvr:
- dmi.product.family: ProLiant
- dmi.product.name: ProLiant DL380 G7
- dmi.sys.vendor: HP
+ [Fix]
+
+ The following commits fix the problem, and all landed in 5.6-rc1:
+
+ commit 125d98edd11464c8e0ec9eaaba7d682d0f832686
+ Author: Coly Li <col...@suse.de>
+ Date: Fri Jan 24 01:01:40 2020 +0800
+ Subject: bcache: remove member accessed from struct btree
+ Link:
https://github.com/torvalds/linux/commit/125d98edd11464c8e0ec9eaaba7d682d0f832686
+
+ commit d5c9c470b01177e4d90cdbf178b8c7f37f5b8795
+ Author: Coly Li <col...@suse.de>
+ Date: Fri Jan 24 01:01:41 2020 +0800
+ Subject: bcache: reap c->btree_cache_freeable from the tail in bch_mca_scan()
+ Link:
https://github.com/torvalds/linux/commit/d5c9c470b01177e4d90cdbf178b8c7f37f5b8795
+
+ commit e3de04469a49ee09c89e80bf821508df458ccee6
+ Author: Coly Li <col...@suse.de>
+ Date: Fri Jan 24 01:01:42 2020 +0800
+ Subject: bcache: reap from tail of c->btree_cache in bch_mca_scan()
+ Link:
https://github.com/torvalds/linux/commit/e3de04469a49ee09c89e80bf821508df458ccee6
+
+ The first commit is a dependency to the second and third commits.
+
+ The first commit is a dependency of the other two. The first commit
+ removes a "recently accessed" marker, used to indicate if a particular
+ cache has been used recently, and if it has been, not consider it for
+ cache eviction. The commit mentions that under heavy IO, all caches will
+ end up being recently accessed, and nothing will ever be shrunk.
+
+ The second commit changes a previous design decision of skipping the
+ first 3 caches to shrink, since it is a common case to call
+ bch_mca_scan() with nr being 1, or 2, just like 0 was common in the very
+ first commit I mentioned. This time, if we land on 1 or 2, the loop
+ exits and nothing happens, and we waste time waiting on locks, just like
+ the very first commit I mentioned. The fix is to try shrink caches from
+ the tail of the list, and not the beginning.
+
+ The third commit fixes a minor issue where we don't want to re-arrange
+ the linked list c->btree_cache, which is what the second commit ended up
+ doing, and instead, just shrink the cache at the end of the linked list,
+ and not change the order.
+
+ All commits are clean cherry picks to Bionic and Focal.
+
+ [Testcase]
+
+ This is kind of hard to test, since the problem shows up in production
+ environments that are under constant IO pressure, with many different
+ items entering and leaving the cache.
+
+ The Launchpad git server is currently suffering this issue, and has been
+ sitting at a constant IO wait of 1 second / slightly over 1 second which
+ was causing slow response times, which was leading to build failures
+ when git clones ended up timing out.
+
+ We installed a test kernel, which is available in the following PPA:
+
+ https://launchpad.net/~mruffell/+archive/ubuntu/sf294907-test
+
+ Once the test kernel had been installed, IO wait times with the shrinker
+ enabled dropped to normal levels, and the git server became responsive
+ again. We have been monitoring the performance of the git server and
+ watching IO wait times in grafana over the past week, and everything is
+ looking good, and indicate that these patches solve the issue.
+
+ [Regression Potential]
+
+ If a regression were to occur, it would only affect users of bcache who
+ have the shrinker enabled, which I believe is the default setting in
+ bcache deployments.
+
+ In that case, users could disable the shrinker as a workaround until a fix is
available. You can disable the shrinker with:
+ "sudo bash -c "echo 1 >
/sys/fs/bcache/<uuid>/internal/btree_shrinker_disabled""
+
+ The patches remove the "recently accessed" marker, which changes the
+ behaviour slightly when it comes to deciding what to evict from the
+ cache. Some workloads that aren't under IO pressure may see a difference
+ in what items are evicted from the cache, which may slightly change
+ bcache's performance profile.
+
+ Since the patches prune the cache from the tail of the cache linked
+ list, we will likely end up pruning more nodes than previously, since it
+ was common to land on the first 3 caches, which were hard coded to be
+ ignored and not pruned, which may also slightly change the bcache's
+ performance profile.
** Description changed:
BugLink: https://bugs.launchpad.net/bugs/1898786
[Impact]
Systems that utilise bcache can experience extremely high IO wait times
when under constant IO pressure. The IO wait times seem to stay at a
consistent 1 second, and never drop as long as the bcache shrinker is
enabled.
If you disable the shrinker, then IO wait drops significantly to normal
levels.
We did some perf analysis, and it seems we spend a huge amount of time
in bch_mca_scan(), likely waiting for the mutex "&c->bucket_lock".
Looking at the recent commits in Bionic, we found the following commit
merged in upstream 5.1-rc1 and backported to 4.15.0-87-generic through
upstream stable:
commit 9fcc34b1a6dd4b8e5337e2b6ef45e428897eca6b
Author: Coly Li <col...@suse.de>
Date: Wed Nov 13 16:03:24 2019 +0800
Subject: bcache: at least try to shrink 1 node in bch_mca_scan()
- Link:
https://github.com/torvalds/linux/commit/9fcc34b1a6dd4b8e5337e2b6ef45e428897eca6b
+ Link:
https://github.com/torvalds/linux/commit/9fcc34b1a6dd4b8e5337e2b6ef45e428897eca6b
It mentions in the description that:
> If sc->nr_to_scan is smaller than c->btree_pages, after the above
> calculation, variable 'nr' will be 0 and nothing will be shrunk. It is
> frequeently observed that only 1 or 2 is set to sc->nr_to_scan and make
> nr to be zero. Then bch_mca_scan() will do nothing more then acquiring
- > and releasing mutex c->bucket_lock.
+ > and releasing mutex c->bucket_lock.
This seems to be what is going on here, but the above commit only
addresses when nr is 0.
From what I can see, the problems we are experiencing are when nr is 1
or 2, and again, we just waste time in bch_mca_scan() waiting on
c->bucket_lock, only to release c->bucket_lock since the shrinker loop
never executes since there is no work to do.
[Fix]
The following commits fix the problem, and all landed in 5.6-rc1:
commit 125d98edd11464c8e0ec9eaaba7d682d0f832686
Author: Coly Li <col...@suse.de>
Date: Fri Jan 24 01:01:40 2020 +0800
Subject: bcache: remove member accessed from struct btree
Link:
https://github.com/torvalds/linux/commit/125d98edd11464c8e0ec9eaaba7d682d0f832686
commit d5c9c470b01177e4d90cdbf178b8c7f37f5b8795
Author: Coly Li <col...@suse.de>
Date: Fri Jan 24 01:01:41 2020 +0800
Subject: bcache: reap c->btree_cache_freeable from the tail in bch_mca_scan()
Link:
https://github.com/torvalds/linux/commit/d5c9c470b01177e4d90cdbf178b8c7f37f5b8795
commit e3de04469a49ee09c89e80bf821508df458ccee6
Author: Coly Li <col...@suse.de>
Date: Fri Jan 24 01:01:42 2020 +0800
Subject: bcache: reap from tail of c->btree_cache in bch_mca_scan()
- Link:
https://github.com/torvalds/linux/commit/e3de04469a49ee09c89e80bf821508df458ccee6
-
- The first commit is a dependency to the second and third commits.
+ Link:
https://github.com/torvalds/linux/commit/e3de04469a49ee09c89e80bf821508df458ccee6
The first commit is a dependency of the other two. The first commit
removes a "recently accessed" marker, used to indicate if a particular
cache has been used recently, and if it has been, not consider it for
cache eviction. The commit mentions that under heavy IO, all caches will
end up being recently accessed, and nothing will ever be shrunk.
The second commit changes a previous design decision of skipping the
first 3 caches to shrink, since it is a common case to call
bch_mca_scan() with nr being 1, or 2, just like 0 was common in the very
first commit I mentioned. This time, if we land on 1 or 2, the loop
exits and nothing happens, and we waste time waiting on locks, just like
the very first commit I mentioned. The fix is to try shrink caches from
the tail of the list, and not the beginning.
The third commit fixes a minor issue where we don't want to re-arrange
the linked list c->btree_cache, which is what the second commit ended up
doing, and instead, just shrink the cache at the end of the linked list,
and not change the order.
All commits are clean cherry picks to Bionic and Focal.
[Testcase]
This is kind of hard to test, since the problem shows up in production
environments that are under constant IO pressure, with many different
items entering and leaving the cache.
The Launchpad git server is currently suffering this issue, and has been
sitting at a constant IO wait of 1 second / slightly over 1 second which
was causing slow response times, which was leading to build failures
when git clones ended up timing out.
We installed a test kernel, which is available in the following PPA:
https://launchpad.net/~mruffell/+archive/ubuntu/sf294907-test
Once the test kernel had been installed, IO wait times with the shrinker
enabled dropped to normal levels, and the git server became responsive
again. We have been monitoring the performance of the git server and
watching IO wait times in grafana over the past week, and everything is
looking good, and indicate that these patches solve the issue.
[Regression Potential]
If a regression were to occur, it would only affect users of bcache who
have the shrinker enabled, which I believe is the default setting in
bcache deployments.
- In that case, users could disable the shrinker as a workaround until a fix is
available. You can disable the shrinker with:
+ In that case, users could disable the shrinker as a workaround until a fix is
available. You can disable the shrinker with:
"sudo bash -c "echo 1 >
/sys/fs/bcache/<uuid>/internal/btree_shrinker_disabled""
The patches remove the "recently accessed" marker, which changes the
behaviour slightly when it comes to deciding what to evict from the
cache. Some workloads that aren't under IO pressure may see a difference
in what items are evicted from the cache, which may slightly change
bcache's performance profile.
Since the patches prune the cache from the tail of the cache linked
list, we will likely end up pruning more nodes than previously, since it
was common to land on the first 3 caches, which were hard coded to be
ignored and not pruned, which may also slightly change the bcache's
performance profile.
** Tags added: focal
** Tags added: sts
--
You received this bug notification because you are a member of Ubuntu
Bugs, which is subscribed to Ubuntu.
https://bugs.launchpad.net/bugs/1898786
Title:
bcache: Issues with large IO wait in bch_mca_scan() when shrinker is
enabled
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1898786/+subscriptions
--
ubuntu-bugs mailing list
ubuntu-bugs@lists.ubuntu.com
https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
