From: Keith Busch <kbusch@kernel.org> Date: 2023-05-03 16:29:04
On Tue, May 02, 2023 at 08:54:12PM +0800, jiweisun126@126.com wrote:
According to the above two logs, we can know the nvme_irq() cost too much
time, in the above case, about 4.8 second. And we can also know that the
main bottlenecks is in the competition for the spin lock pool->lock.
I have a fix that makes pool->lock critical section much shorter and constant
time. It was staged in mm tree for months, but mysteriously it's missing...
From: Keith Busch <kbusch@kernel.org> Date: 2023-05-03 23:42:30
On Wed, May 03, 2023 at 10:28:53AM -0600, Keith Busch wrote:
On Tue, May 02, 2023 at 08:54:12PM +0800, jiweisun126@126.com wrote:
quoted
According to the above two logs, we can know the nvme_irq() cost too much
time, in the above case, about 4.8 second. And we can also know that the
main bottlenecks is in the competition for the spin lock pool->lock.
I have a fix that makes pool->lock critical section much shorter and constant
time. It was staged in mm tree for months, but mysteriously it's missing...
On Wed, May 03, 2023 at 05:42:22PM -0600, Keith Busch wrote:
On Wed, May 03, 2023 at 10:28:53AM -0600, Keith Busch wrote:
quoted
On Tue, May 02, 2023 at 08:54:12PM +0800, jiweisun126@126.com wrote:
quoted
According to the above two logs, we can know the nvme_irq() cost too much
time, in the above case, about 4.8 second. And we can also know that the
main bottlenecks is in the competition for the spin lock pool->lock.
I have a fix that makes pool->lock critical section much shorter and constant
time. It was staged in mm tree for months, but mysteriously it's missing...
On Thu, May 04, 2023 at 11:39:53AM +0200, Niklas Cassel wrote:
On Wed, May 03, 2023 at 05:42:22PM -0600, Keith Busch wrote:
quoted
On Wed, May 03, 2023 at 10:28:53AM -0600, Keith Busch wrote:
quoted
On Tue, May 02, 2023 at 08:54:12PM +0800, jiweisun126@126.com wrote:
quoted
According to the above two logs, we can know the nvme_irq() cost too much
time, in the above case, about 4.8 second. And we can also know that the
main bottlenecks is in the competition for the spin lock pool->lock.
I have a fix that makes pool->lock critical section much shorter and constant
time. It was staged in mm tree for months, but mysteriously it's missing...
It seems like the additional lines in
2d55c16c0c54 ("dmapool: create/destroy cleanup") is explained by the
maintainer (probably accidentally) reverting additional patches in that
very same commit.
It seems like that commit reverted all changes to mm/dmapool.c since v6.3:
$ git log --oneline 2d55c16c0c54325bf15286cfa6ba6c268036b9e4 --not v6.3 mm/dmapool.c
2d55c16c0c54 dmapool: create/destroy cleanup
a4de12a032fa dmapool: link blocks across pages
9d062a8a4c6d dmapool: don't memset on free twice
887aef615818 dmapool: simplify freeing
2591b516533b dmapool: consolidate page initialization
36d1a28921a4 dmapool: rearrange page alloc failure handling
52e7d5653979 dmapool: move debug code to own functions
19f504584038 dmapool: speedup DMAPOOL_DEBUG with init_on_alloc
347e4e44c0a9 dmapool: cleanup integer types
65216545436b dmapool: use sysfs_emit() instead of scnprintf()
7f796d141c07 dmapool: remove checks for dev == NULL
$ git diff v6.3 2d55c16c0c54325bf15286cfa6ba6c268036b9e4 mm/dmapool.c
<nothing>
Should probably tell Andrew so that he has time to send out a new PR
before the merge window closes. (I added him in To: .)
He should probably pick up this fix too:
https://patchwork.kernel.org/project/linux-mm/patch/20230221165400.1595247-1-kbusch@meta.com/
Kind regards,
Niklas
From: Keith Busch <kbusch@kernel.org> Date: 2023-05-04 15:06:30
On Thu, May 04, 2023 at 10:12:46AM +0000, Niklas Cassel wrote:
On Thu, May 04, 2023 at 11:39:53AM +0200, Niklas Cassel wrote:
quoted
Something is fishy here...
(Perhaps the maintainer did a git revert instead of applying the fix...
and accidentally squashed the revert with a proper commit...
But even that does not make sense, as there simply seems to be too many
lines changed in 2d55c16c0c54 ("dmapool: create/destroy cleanup") for that
to be the case...)
It seems like the additional lines in
2d55c16c0c54 ("dmapool: create/destroy cleanup") is explained by the
maintainer (probably accidentally) reverting additional patches in that
very same commit.
It seems like that commit reverted all changes to mm/dmapool.c since v6.3:
Spot on, thanks for confirming! Somehow a series revert was squahed into
the final patch. :(
We reached the same conclusion pretty late yesterday, so I'll wait for
Andrew to suggest how to proceed. I think we have to rebase whole series
with the correct final patch and resend the pull.
$ git log --oneline 2d55c16c0c54325bf15286cfa6ba6c268036b9e4 --not v6.3 mm/dmapool.c
2d55c16c0c54 dmapool: create/destroy cleanup
a4de12a032fa dmapool: link blocks across pages
9d062a8a4c6d dmapool: don't memset on free twice
887aef615818 dmapool: simplify freeing
2591b516533b dmapool: consolidate page initialization
36d1a28921a4 dmapool: rearrange page alloc failure handling
52e7d5653979 dmapool: move debug code to own functions
19f504584038 dmapool: speedup DMAPOOL_DEBUG with init_on_alloc
347e4e44c0a9 dmapool: cleanup integer types
65216545436b dmapool: use sysfs_emit() instead of scnprintf()
7f796d141c07 dmapool: remove checks for dev == NULL
$ git diff v6.3 2d55c16c0c54325bf15286cfa6ba6c268036b9e4 mm/dmapool.c
<nothing>
Should probably tell Andrew so that he has time to send out a new PR
before the merge window closes. (I added him in To: .)
He should probably pick up this fix too:
https://patchwork.kernel.org/project/linux-mm/patch/20230221165400.1595247-1-kbusch@meta.com/
Andrew actually squashed that fix into the original patch.
On Thu, May 04, 2023 at 09:06:20AM -0600, Keith Busch wrote:
On Thu, May 04, 2023 at 10:12:46AM +0000, Niklas Cassel wrote:
quoted
On Thu, May 04, 2023 at 11:39:53AM +0200, Niklas Cassel wrote:
quoted
Something is fishy here...
(Perhaps the maintainer did a git revert instead of applying the fix...
and accidentally squashed the revert with a proper commit...
But even that does not make sense, as there simply seems to be too many
lines changed in 2d55c16c0c54 ("dmapool: create/destroy cleanup") for that
to be the case...)
It seems like the additional lines in
2d55c16c0c54 ("dmapool: create/destroy cleanup") is explained by the
maintainer (probably accidentally) reverting additional patches in that
very same commit.
It seems like that commit reverted all changes to mm/dmapool.c since v6.3:
Spot on, thanks for confirming! Somehow a series revert was squahed into
the final patch. :(
We reached the same conclusion pretty late yesterday, so I'll wait for
Andrew to suggest how to proceed. I think we have to rebase whole series
with the correct final patch and resend the pull.
quoted
$ git log --oneline 2d55c16c0c54325bf15286cfa6ba6c268036b9e4 --not v6.3 mm/dmapool.c
2d55c16c0c54 dmapool: create/destroy cleanup
a4de12a032fa dmapool: link blocks across pages
9d062a8a4c6d dmapool: don't memset on free twice
887aef615818 dmapool: simplify freeing
2591b516533b dmapool: consolidate page initialization
36d1a28921a4 dmapool: rearrange page alloc failure handling
52e7d5653979 dmapool: move debug code to own functions
19f504584038 dmapool: speedup DMAPOOL_DEBUG with init_on_alloc
347e4e44c0a9 dmapool: cleanup integer types
65216545436b dmapool: use sysfs_emit() instead of scnprintf()
7f796d141c07 dmapool: remove checks for dev == NULL
Hello Keith, Andrew,
Note that the first four patches were not part of Keith's series,
but they were reverted as well.
Andrew actually squashed that fix into the original patch.
Ok, strange why there was a revert done at all then.
Kind regards,
Niklas
From: Keith Busch <kbusch@kernel.org> Date: 2023-05-15 20:41:01
On Tue, May 02, 2023 at 08:54:12PM +0800, jiweisun126@126.com wrote:
From: Jiwei Sun <redacted>
A soft lockup issue will be triggered when do fio test on a 448-core
server, such as the following warning:
...
According to the above two logs, we can know the nvme_irq() cost too much
time, in the above case, about 4.8 second. And we can also know that the
main bottlenecks is in the competition for the spin lock pool->lock.
The most recent 6.4-rc has included a significant changeset to the pool
allocator that may show a considerable difference in pool->lock timing.
It would be interesting to hear if it changes your observation with your
448-core setup. Would you be able to re-run your experiements that
produced the soft lockup with this kernel on that machine?
From: Jiwei Sun <hidden> Date: 2023-05-16 14:18:58
Hi Keith,
On 2023/5/16 04:40, Keith Busch wrote:
On Tue, May 02, 2023 at 08:54:12PM +0800, jiweisun126@126.com wrote:
quoted
From: Jiwei Sun <redacted>
A soft lockup issue will be triggered when do fio test on a 448-core
server, such as the following warning:
...
quoted
According to the above two logs, we can know the nvme_irq() cost too much
time, in the above case, about 4.8 second. And we can also know that the
main bottlenecks is in the competition for the spin lock pool->lock.
The most recent 6.4-rc has included a significant changeset to the pool
allocator that may show a considerable difference in pool->lock timing.
It would be interesting to hear if it changes your observation with your
448-core setup. Would you be able to re-run your experiements that
produced the soft lockup with this kernel on that machine?
We have done some testes with the latest kernel, the issue can not be reproduced,
and we have analyzed the ftrace log of nvme_irq, we did NOT find any competition for
the spin lock pool->lock, and all the dma_pool_free function completed within 2us.
287) | dma_pool_free() {
287) 0.150 us | _raw_spin_lock_irqsave();
287) 0.421 us | _raw_spin_unlock_irqrestore();
287) 1.472 us | }
+-- 63 lines: 287) | mempool_free() {-----------
435) | dma_pool_free() {
435) 0.170 us | _raw_spin_lock_irqsave();
435) 0.210 us | _raw_spin_unlock_irqrestore();
435) 1.172 us | }
+--145 lines: 435) | mempool_free() {---------
317) | dma_pool_free() {
317) 0.160 us | _raw_spin_lock_irqsave();
317) 0.401 us | _raw_spin_unlock_irqrestore();
317) 1.252 us | }
Based on the test results and analysis of the code principles, your patch has fixed this performance issue.
By the way, another task hung issue was triggered in the test. We are analyzing it, but this is another story,
we can discuss it in other thread.
Thanks,
Regards,
Jiwei