| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Date: Mon, 23 Dec 2013 05:03:18 +0000
From: Phillip Lougher <phillip@...gher.demon.co.uk>
To: Chanho Min <chanho.min@....com>
CC: Phillip Lougher <phillip@...ashfs.org.uk>,
linux-kernel@...r.kernel.org, HyoJun Im <hyojun.im@....com>,
gunho.lee@....com, Minchan Kim <minchan@...nel.org>
Subject: Re: [PATCH] Squashfs: add asynchronous read support
On 16/12/13 05:30, Chanho Min wrote:
> This patch removes synchronous wait for the up-to-date of buffer in the
> file system level. Instead all operations after submit_bh are moved into
> the End-of-IO handler and its associated workeque. It decompresses/copies
> data into pages and unlock them asynchronously.
>
> This patch enhances the performance of Squashfs in most cases.
> Especially, large file reading is improved significantly.
Hi,
The following is the summarised results of a set of
comprehensive tests of the asynchronous patch against the current
synchronous Squashfs readpage implementation.
The following tables should be fairly self-explanatory, but,
the testing methodology was:
Generate a series of Squashfs filesystems, with block size
1024K, 512K, 256K, 128K and 64K.
Then for each filesystem
Run "dd if=/mnt/file of=/dev/null bs=X"
Where X is 4K, 8K, 16K, 32K, 64K, 128K, 256K, 512K, and 1024K
For each dd, run it against six different Squashfs modules,
configured with the following different options:
1. SQUASHFS_READ_DATA_ASYNC selected, SQUASHFS_DECOMP_SINGLE selected
i.e. Async patch and single threaded decompression
== Asyn Single in following tables
2. SQUASHFS_READ_DATA_ASYNC *not* selected, SQUASHFS_DECOMP_SINGLE selected
i.e. No Async patch and single threaded decompression
== No Asyn Single in following tables
3. SQUASHFS_READ_DATA_ASYNC selected, SQUASHFS_DECOMP_MULTI selected
i.e. Async patch and multi-threaded decompression
== Asyn Multi in following tables
4. SQUASHFS_READ_DATA_ASYNC *not* selected, SQUASHFS_DECOMP_MULTI selected
i.e. No Async patch and multi-threaded decompression
== No Asyn Multi in following tables
5. SQUASHFS_READ_DATA_ASYNC selected, SQUASHFS_DECOMP_MULTI_PERCPU selected
i.e. Async patch and percpu multi-threaded decompression
== Asyn Percpu in following tables
6. SQUASHFS_READ_DATA_ASYNC *not* selected, SQUASHFS_DECOMP_MULTI_PERCPU selected
i.e. No Async patch and percpu multi-threaded decompression
== No Asyn Percpu in following tables
The figures in the following tables are the MB/s reported by dd.
The tests were performed on a KVM guest with 4 cores and 4Gb of
memory, running on a core i5 based host.
The Squashfs filesystem was on "/dev/hdb".
/mnt/file is a 3Gb file, average compression 22% (635 Mb)
Squashfs: gzip filesystem 1024K blocks
Asyn No Asyn Asyn No Asyn Asyn No Asyn
Single Single Multi Multi Percpu Percpu
-------------------------------------------------------
4K: 89.4 97.5 89.9 98.1 90.6 99.1
8K: 89.9 99.0 89.7 99.4 90.3 99.4
16K: 90.6 99.8 90.8 100 90.2 97.0
32K: 90.3 98.7 90.3 98.0 89.9 101
64K: 90.3 97.6 90.2 97.1 90.1 99.7
128K: 90.4 98.6 90.2 97.6 90.7 98.5
256K: 89.7 96.9 89.8 99.2 90.2 101
512K: 89.7 98.9 90.8 98.1 89.4 97.8
1024K: 89.3 98.0 89.6 98.6 88.7 96.4
Squashfs: gzip filesystem 512K blocks
Asyn No Asyn Asyn No Asyn Asyn No Asyn
Single Single Multi Multi Percpu Percpu
-------------------------------------------------------
4K: 68.5 94.9 67.6 99.0 68.9 97.0
8K: 69.3 101 68.9 94.3 69.0 97.2
16K: 68.9 98.6 69.4 98.9 68.8 98.0
32K: 68.6 96.5 69.4 98.9 69.4 108
64K: 68.7 92.9 69.7 101 68.8 98.2
128K: 67.4 102 68.7 90.3 69.4 100
256K: 68.7 95.1 68.2 99.7 68.5 97.7
512K: 69.9 114 82.0 104 74.2 94.4
1024K: 71.6 105 79.2 105 69.1 98.0
Squashfs: gzip filesystem 256K blocks
Asyn No Asyn Asyn No Asyn Asyn No Asyn
Single Single Multi Multi Percpu Percpu
-------------------------------------------------------
4K: 53.6 92.2 54.6 87.5 53.7 82.1
8K: 53.5 87.3 53.5 85.0 53.5 85.7
16K: 53.1 89.0 53.8 95.7 53.5 91.1
32K: 54.0 95.9 53.8 98.7 53.9 85.3
64K: 53.7 86.9 53.4 103 53.4 86.3
128K: 53.2 94.4 53.6 100 53.7 97.9
256K: 55.5 101 53.0 94.1 53.3 87.0
512K: 53.1 93.0 53.4 87.7 53.2 89.8
1024K: 53.2 91.4 52.7 91.3 53.0 95.4
A couple of points about the above can be noticed:
1. With a Squashfs block size of 256K and greater, Squashfs
readpage() does its own readahead. This means the asynchronous
readpage is never called multiply (to run in parallel), because
there is never any more work to do after the first readpage().
The above results therefore reflect the basic performance of
the asynchronous readpage implementation versus the
synchronous readpage implementation.
2. It can be seen in all cases the asynchronous readpage implementation
performs worse than the synchronous readpage implementation.
This varies from 10% worse (1024K blocks) to a huge 44% worse
(256K blocks).
In otherwords, the smaller the filesystem block size the more
readpage calls, and the greater performance hit.
Squashfs: gzip filesystem 128K blocks
Asyn No Asyn Asyn No Asyn Asyn No Asyn
Single Single Multi Multi Percpu Percpu
-------------------------------------------------------
4K: 44.7 49.2 43.0 47.0 42.7 48.9
8K: 43.0 48.6 43.0 48.2 43.0 49.8
16K: 42.9 47.9 43.0 47.5 43.1 47.4
32K: 42.9 47.2 43.0 46.1 42.9 47.1
64K: 50.7 47.0 55.1 53.1 55.2 49.6
128K: 51.1 47.6 54.9 49.2 55.7 48.7
256K: 51.0 49.5 54.7 48.2 57.3 49.3
512K: 53.6 48.2 55.2 47.6 54.9 48.3
1024K: 51.1 47.9 54.7 47.5 54.6 46.5
A couple of points about the above can be noticed:
1. A filesystem block size of 128K means a single readpage call
no longer performs all the readahead. Thus allowing the
possibility of simultaneous asynchronous readpage calls.
2. dd block sizes of 32K and less show worse performance
for the asynchronous readpage implementation, similar to
the previous results.
An ftrace of the kernel shows no parallel async readpage calls
are taking place.
3. Block sizes of 64K and above show readahead taking place, with
parallel asynchronous readpages.
This is confirmed by an ftrace of the kernel.
The performance improvement ranges from 7.9% to 16%, or 1.079x and
1.16x the performance of the synchronous readpage() implementation.
Overall of the above 108 datapoint sets, 15 show an improvement
of between 7.9%-16%, and 93 show a performance decrease of
between 10%-44%. 86% of the performance tests are worse.
This is the not terribly good "good" results.
Worse is the fact I have got constant kernel oopses testing the
asynchronous patch (note I received no kernel oopses without the
asynchronous patch). I have included two of the kernel oopses
here. All the kernel oopses are different, but all point to the
fact the asynchronous patch introduces races with the page state
within the page cache/VFS layer.
1. Ooops 1.
BUG: Bad page state in process kworker/0:3 pfn:11f618
page:ffffea00047d8600 count:0 mapcount:0 mapping:ffff88003c1081b8 index:0x2ea8
page flags: 0x800000000000000a(error|uptodate)
BUG: Bad page state in process kworker/0:3 pfn:5020b
page:ffffea00014082c0 count:0 mapcount:0 mapping:ffff88003c1081b8 index:0x2ea9
page flags: 0x400000000000000a(error|uptodate)
BUG: Bad page state in process kworker/0:3 pfn:5020a
page:ffffea0001408280 count:0 mapcount:0 mapping:ffff88003c1081b8 index:0x2eaa
page flags: 0x400000000000000a(error|uptodate)
BUG: Bad page state in process kworker/0:3 pfn:50209
page:ffffea0001408240 count:0 mapcount:0 mapping:ffff88003c1081b8 index:0x2eab
page flags: 0x400000000000000a(error|uptodate)
BUG: Bad page state in process kworker/0:3 pfn:50208
page:ffffea0001408200 count:0 mapcount:0 mapping:ffff88003c1081b8 index:0x2eac
page flags: 0x400000000000000a(error|uptodate)
BUG: Bad page state in process kworker/0:3 pfn:50207
page:ffffea00014081c0 count:0 mapcount:0 mapping:ffff88003c1081b8 index:0x2ead
page flags: 0x400000000000000a(error|uptodate)
BUG: Bad page state in process kworker/0:3 pfn:50205
page:ffffea0001408140 count:0 mapcount:0 mapping:ffff88003c1081b8 index:0x2eae
page flags: 0x400000000000000a(error|uptodate)
BUG: Bad page state in process kworker/0:3 pfn:50204
page:ffffea0001408100 count:0 mapcount:0 mapping:ffff88003c1081b8 index:0x2eaf
page flags: 0x400000000000000a(error|uptodate)
stack segment: 0000 [#1] SMP
Modules linked in: squashfs [last unloaded: squashfs]
CPU: 0 PID: 2698 Comm: klogd Tainted: G B 3.13.0-rc3+ #32
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
task: ffff8800da85cec0 ti: ffff88011a6b6000 task.ti: ffff88011a6b6000
RIP: 0010:[<ffffffff81106026>] [<ffffffff81106026>] __kmalloc_track_caller+0x56/0x130
RSP: 0018:ffff88011a6b7c20 EFLAGS: 00010206
RAX: 0000000000000000 RBX: ffff8800dbbd9700 RCX: 000000000009689f
RDX: 000000000009689e RSI: 0000000000000000 RDI: 00000000000001bf
RBP: 32206365443e313c R08: 0000000000015480 R09: 0000000000000003
R10: ffff8800da85cec0 R11: 0000000000000246 R12: 00000000000106d0
R13: 00000000000001c0 R14: ffffffff81658bb0 R15: ffff88011b001840
FS: 00007fe94d6c36f0(0000) GS:ffff88011fc00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: ffffffffff600400 CR3: 000000011a60c000 CR4: 00000000000006f0
Stack:
ffff8800dbbd9700 ffff88011a6b7c8f 00000000000004d0 00000000000001c0
0000000000000000 7fffffffffffffff ffffffff81658ae9 ffff8800dbbd9700
00000000000004d0 0000000000000000 ffff88011b001900 000000000000004d
Call Trace:
[<ffffffff81658ae9>] ? __kmalloc_reserve.isra.40+0x29/0x80
[<ffffffff81658bb0>] ? __alloc_skb+0x70/0x280
[<ffffffff81652b77>] ? sock_alloc_send_pskb+0x197/0x3d0
[<ffffffff816f0ce5>] ? unix_dgram_sendmsg+0x165/0x640
[<ffffffff81113aaf>] ? path_lookupat+0x6f/0x790
[<ffffffff8164f8b5>] ? sock_aio_write+0xf5/0x130
[<ffffffff810342ff>] ? __do_page_fault+0x2af/0x460
[<ffffffff81107e8c>] ? do_sync_write+0x5c/0x90
[<ffffffff81108575>] ? vfs_write+0x155/0x1c0
[<ffffffff81108b48>] ? SyS_write+0x48/0xa0
[<ffffffff81725352>] ? system_call_fastpath+0x16/0x1b
Code: 89 c7 76 61 49 8b 0f 65 48 03 0c 25 c8 cc 00 00 48 8b 51 08 48 8b 29 48 85 ed 0f 84 a8 00 00 00 49 63 47 20 48 8d 4a 01 4d 8b 07 <48> 8b 5c 05 00 48 89 e8 65 49 0f c7 08 0f 94 c0 84 c0 74 c5 49
RIP [<ffffffff81106026>] __kmalloc_track_caller+0x56/0x130
RSP <ffff88011a6b7c20>
---[ end trace 5e8d5e5a2d98a915 ]---
note: klogd[2698] exited with preempt_count 1
------------[ cut here ]------------
WARNING: CPU: 0 PID: 1495 at fs/buffer.c:1204 __find_get_block+0x1c5/0x220()
VFS: brelse: Trying to free free buffer
Modules linked in: squashfs [last unloaded: squashfs]
CPU: 0 PID: 1495 Comm: jbd2/hda1-8 Tainted: G B D 3.13.0-rc3+ #32
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
0000000000000009 ffffffff8171e362 ffff8800dbb43b38 ffffffff8103ca27
ffff880113bbb270 ffff8800dbb43b88 0000000000000008 ffff880113bbb000
0000000000001000 ffffffff8103ca8c ffffffff819818c8 0000000000000018
Call Trace:
[<ffffffff8171e362>] ? dump_stack+0x41/0x51
[<ffffffff8103ca27>] ? warn_slowpath_common+0x77/0x90
[<ffffffff8103ca8c>] ? warn_slowpath_fmt+0x4c/0x50
[<ffffffff81136b85>] ? __find_get_block+0x1c5/0x220
[<ffffffff811370ae>] ? __getblk+0x9e/0x2e0
[<ffffffff811f2980>] ? jbd2_journal_get_descriptor_buffer+0x30/0x90
[<ffffffff811eaa71>] ? journal_submit_commit_record.isra.10+0x61/0x1c0
[<ffffffff811ebcae>] ? jbd2_journal_commit_transaction+0x10de/0x17d0
[<ffffffff81065d13>] ? try_to_wake_up+0xd3/0x290
[<ffffffff811f0ee5>] ? kjournald2+0xb5/0x250
[<ffffffff8106f980>] ? __wake_up_sync+0x10/0x10
[<ffffffff811f0e30>] ? commit_timeout+0x10/0x10
[<ffffffff8105a226>] ? kthread+0xc6/0xe0
[<ffffffff8105a160>] ? kthread_create_on_node+0x1a0/0x1a0
[<ffffffff817252ac>] ? ret_from_fork+0x7c/0xb0
[<ffffffff8105a160>] ? kthread_create_on_node+0x1a0/0x1a0
---[ end trace 5e8d5e5a2d98a916 ]---
------------[ cut here ]------------
WARNING: CPU: 0 PID: 1495 at fs/buffer.c:1204 __find_get_block+0x1c5/0x220()
VFS: brelse: Trying to free free buffer
Modules linked in: squashfs [last unloaded: squashfs]
CPU: 0 PID: 1495 Comm: jbd2/hda1-8 Tainted: G B D W 3.13.0-rc3+ #32
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
0000000000000009 ffffffff8171e362 ffff8800dbb43b98 ffffffff8103ca27
ffff880113bbb2d8 ffff8800dbb43be8 0000000000000008 ffff880060e47f70
0000000000001000 ffffffff8103ca8c ffffffff819818c8 0000000000000018
Call Trace:
[<ffffffff8171e362>] ? dump_stack+0x41/0x51
[<ffffffff8103ca27>] ? warn_slowpath_common+0x77/0x90
[<ffffffff8103ca8c>] ? warn_slowpath_fmt+0x4c/0x50
[<ffffffff81136b85>] ? __find_get_block+0x1c5/0x220
[<ffffffff811370ae>] ? __getblk+0x9e/0x2e0
[<ffffffff811f2980>] ? jbd2_journal_get_descriptor_buffer+0x30/0x90
[<ffffffff811eb6aa>] ? jbd2_journal_commit_transaction+0xada/0x17d0
[<ffffffff817209ea>] ? __schedule+0x2aa/0x810
[<ffffffff81065d13>] ? try_to_wake_up+0xd3/0x290
[<ffffffff811f0ee5>] ? kjournald2+0xb5/0x250
[<ffffffff8106f980>] ? __wake_up_sync+0x10/0x10
[<ffffffff811f0e30>] ? commit_timeout+0x10/0x10
[<ffffffff8105a226>] ? kthread+0xc6/0xe0
[<ffffffff8105a160>] ? kthread_create_on_node+0x1a0/0x1a0
[<ffffffff817252ac>] ? ret_from_fork+0x7c/0xb0
[<ffffffff8105a160>] ? kthread_create_on_node+0x1a0/0x1a0
---[ end trace 5e8d5e5a2d98a917 ]---
2. Oops 2
BUG: unable to handle kernel NULL pointer dereference at 0000000000000028
IP: [<ffffffffa05c8ad6>] zlib_uncompress+0xc6/0x190 [squashfs]
PGD 69239067 PUD 89e0e067 PMD 0
Oops: 0000 [#1] SMP
Modules linked in: squashfs [last unloaded: squashfs]
CPU: 1 PID: 4877 Comm: kworker/1:3 Not tainted 3.13.0-rc3+ #32
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
Workqueue: events squashfs_async_work [squashfs]
task: ffff8800da9f3b10 ti: ffff880074e46000 task.ti: ffff880074e46000
RIP: 0010:[<ffffffffa05c8ad6>] [<ffffffffa05c8ad6>] zlib_uncompress+0xc6/0x190 [squashfs]
RSP: 0018:ffff880074e47d18 EFLAGS: 00010283
RAX: 00000000000002f4 RBX: 0000000000000003 RCX: 0000000000000000
RDX: ffff880000000000 RSI: 0000000000000000 RDI: ffff8800db3bc640
RBP: ffff88011a62e600 R08: 000000000000010c R09: 0000000000000881
R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000881
R13: 0000000000000000 R14: 000000000000010c R15: ffff88011a5e0c60
FS: 0000000000000000(0000) GS:ffff88011fc80000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 0000000000000028 CR3: 0000000057bd8000 CR4: 00000000000006e0
Stack:
ffff88011a5e08a8 ffff8800db270800 ffff8800db270800 ffff88011a5e08a8
ffff88011a5e08a0 ffff88011a62e600 0000000000000003 000000000000010c
ffffffffa05c83f4 ffff8800db3bc640 ffff8800db3bc640 00000881000127c0
Call Trace:
[<ffffffffa05c83f4>] ? squashfs_decompress+0x64/0xa0 [squashfs]
[<ffffffffa05c4109>] ? squashfs_buffer_read_async+0x69/0x2e0 [squashfs]
[<ffffffff810536d5>] ? process_one_work+0x175/0x3f0
[<ffffffff81054224>] ? worker_thread+0x114/0x3a0
[<ffffffff81054110>] ? manage_workers.isra.26+0x290/0x290
[<ffffffff8105a226>] ? kthread+0xc6/0xe0
[<ffffffff8105a160>] ? kthread_create_on_node+0x1a0/0x1a0
[<ffffffff817252ac>] ? ret_from_fork+0x7c/0xb0
[<ffffffff8105a160>] ? kthread_create_on_node+0x1a0/0x1a0
Code: 8b 47 08 b9 01 00 00 00 85 c0 75 30 41 39 dd 7d 2b 48 8b 44 24 08 49 63 f5 48 8b 74 f5 00 8b 40 08 44 29 f0 44 39 e0 41 0f 4f c4 <4c> 03 76 28 41 29 c4 41 89 47 08 4d 89 37 45 31 f6 41 8b 77 20
RIP [<ffffffffa05c8ad6>] zlib_uncompress+0xc6/0x190 [squashfs]
RSP <ffff880074e47d18>
CR2: 0000000000000028
---[ end trace e66a56dcb454c870 ]---
note: kworker/1:3[4877] exited with preempt_count 1
BUG: unable to handle kernel paging request at ffffffffffffffc8
IP: [<ffffffff8105a85c>] kthread_data+0xc/0x20
PGD 1c0c067 PUD 1c0e067 PMD 0
Oops: 0000 [#2] SMP
Modules linked in: squashfs [last unloaded: squashfs]
CPU: 1 PID: 4877 Comm: kworker/1:3 Tainted: G D 3.13.0-rc3+ #32
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
task: ffff8800da9f3b10 ti: ffff880074e46000 task.ti: ffff880074e46000
RIP: 0010:[<ffffffff8105a85c>] [<ffffffff8105a85c>] kthread_data+0xc/0x20
RSP: 0018:ffff880074e47988 EFLAGS: 00010002
RAX: 0000000000000000 RBX: 0000000000000001 RCX: ffff88011fc927c0
RDX: 000000000000b9c7 RSI: 0000000000000001 RDI: ffff8800da9f3b10
RBP: ffff880074e47a98 R08: 8000000000000000 R09: 0000000000000001
R10: 000000000000b885 R11: 0000000000000000 R12: ffff8800da9f3df0
R13: 0000000000000001 R14: ffff8800da9f3b00 R15: ffff8800da9f3b10
FS: 0000000000000000(0000) GS:ffff88011fc80000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 0000000000000028 CR3: 0000000057bd8000 CR4: 00000000000006e0
Stack:
ffffffff81054d8d ffff88011fc927c0 ffffffff81720b3d ffff8800da9f3b10
ffff880074e47fd8 00000000000127c0 00000000000127c0 ffff8800da9f3b10
0000000000000001 0000000000000000 0000000000000206 ffff880074e47a68
Call Trace:
[<ffffffff81054d8d>] ? wq_worker_sleeping+0xd/0x80
[<ffffffff81720b3d>] ? __schedule+0x3fd/0x810
[<ffffffff812b22eb>] ? debug_object_active_state+0x12b/0x170
[<ffffffff8103d330>] ? will_become_orphaned_pgrp+0xb0/0xb0
[<ffffffff8103e072>] ? do_exit+0x6a2/0x9f0
[<ffffffff81005a8a>] ? oops_end+0x6a/0x90
[<ffffffff8171b805>] ? no_context+0x25e/0x26a
[<ffffffff810342ff>] ? __do_page_fault+0x2af/0x460
[<ffffffff8106d263>] ? idle_balance+0x193/0x1a0
[<ffffffff817243fa>] ? _raw_spin_unlock_irq+0xa/0x10
[<ffffffff81062597>] ? finish_task_switch+0x57/0xa0
[<ffffffff817209ea>] ? __schedule+0x2aa/0x810
[<ffffffff81724be2>] ? page_fault+0x22/0x30
[<ffffffffa05c8ad6>] ? zlib_uncompress+0xc6/0x190 [squashfs]
[<ffffffffa05c8a48>] ? zlib_uncompress+0x38/0x190 [squashfs]
[<ffffffffa05c83f4>] ? squashfs_decompress+0x64/0xa0 [squashfs]
[<ffffffffa05c4109>] ? squashfs_buffer_read_async+0x69/0x2e0 [squashfs]
[<ffffffff810536d5>] ? process_one_work+0x175/0x3f0
[<ffffffff81054224>] ? worker_thread+0x114/0x3a0
[<ffffffff81054110>] ? manage_workers.isra.26+0x290/0x290
[<ffffffff8105a226>] ? kthread+0xc6/0xe0
[<ffffffff8105a160>] ? kthread_create_on_node+0x1a0/0x1a0
[<ffffffff817252ac>] ? ret_from_fork+0x7c/0xb0
[<ffffffff8105a160>] ? kthread_create_on_node+0x1a0/0x1a0
Code: 88 02 00 00 48 8b 40 b8 48 c1 e8 02 83 e0 01 c3 66 66 66 66 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 8b 87 88 02 00 00 <48> 8b 40 c8 c3 66 66 66 66 66 66 2e 0f 1f 84 00 00 00 00 00 0f
RIP [<ffffffff8105a85c>] kthread_data+0xc/0x20
RSP <ffff880074e47988>
CR2: ffffffffffffffc8
---[ end trace e66a56dcb454c871 ]---
Fixing recursive fault but reboot is needed!
hda: lost interrupt
hda: ide_dma_sff_timer_expiry: DMA status (0x64)
hdc: lost interrupt
ðBUG: spinlock lockup suspected on CPU#1, kworker/1:3/4877
lock: 0xffff88011fc927c0, .magic: dead4ead, .owner: kworker/1:3/4877, .owner_cpu: 1
CPU: 1 PID: 4877 Comm: kworker/1:3 Tainted: G D 3.13.0-rc3+ #32
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
0000000088c1cfb8 ffffffff8171e362 ffff88011fc927c0 ffffffff81073169
ffff88011fc927c0 ffff880074e47708 0000000000000000 ffffffff817207de
ffff8800da9f3b10 ffff880074e47fd8 00000000000127c0 00000000000127c0
Call Trace:
[<ffffffff8171e362>] ? dump_stack+0x41/0x51
[<ffffffff81073169>] ? do_raw_spin_lock+0x69/0x140
[<ffffffff817207de>] ? __schedule+0x9e/0x810
[<ffffffff8107d450>] ? wake_up_klogd+0x30/0x40
[<ffffffff8171c3a5>] ? printk+0x54/0x56
[<ffffffff8103e2d9>] ? do_exit+0x909/0x9f0
[<ffffffff81005a8a>] ? oops_end+0x6a/0x90
[<ffffffff8171b805>] ? no_context+0x25e/0x26a
[<ffffffff810342ff>] ? __do_page_fault+0x2af/0x460
[<ffffffff81099deb>] ? __sprint_symbol+0x8b/0xe0
[<ffffffff812a4c06>] ? string.isra.5+0x36/0xe0
[<ffffffff812a504c>] ? symbol_string.isra.10+0x5c/0xa0
[<ffffffff81724be2>] ? page_fault+0x22/0x30
[<ffffffff8105a85c>] ? kthread_data+0xc/0x20
[<ffffffff81054d8d>] ? wq_worker_sleeping+0xd/0x80
[<ffffffff81720b3d>] ? __schedule+0x3fd/0x810
[<ffffffff812b22eb>] ? debug_object_active_state+0x12b/0x170
[<ffffffff8103d330>] ? will_become_orphaned_pgrp+0xb0/0xb0
[<ffffffff8103e072>] ? do_exit+0x6a2/0x9f0
[<ffffffff81005a8a>] ? oops_end+0x6a/0x90
[<ffffffff8171b805>] ? no_context+0x25e/0x26a
[<ffffffff810342ff>] ? __do_page_fault+0x2af/0x460
[<ffffffff8106d263>] ? idle_balance+0x193/0x1a0
[<ffffffff817243fa>] ? _raw_spin_unlock_irq+0xa/0x10
[<ffffffff81062597>] ? finish_task_switch+0x57/0xa0
[<ffffffff817209ea>] ? __schedule+0x2aa/0x810
[<ffffffff81724be2>] ? page_fault+0x22/0x30
[<ffffffffa05c8ad6>] ? zlib_uncompress+0xc6/0x190 [squashfs]
[<ffffffffa05c8a48>] ? zlib_uncompress+0x38/0x190 [squashfs]
[<ffffffffa05c83f4>] ? squashfs_decompress+0x64/0xa0 [squashfs]
[<ffffffffa05c4109>] ? squashfs_buffer_read_async+0x69/0x2e0 [squashfs]
[<ffffffff810536d5>] ? process_one_work+0x175/0x3f0
[<ffffffff81054224>] ? worker_thread+0x114/0x3a0
[<ffffffff81054110>] ? manage_workers.isra.26+0x290/0x290
[<ffffffff8105a226>] ? kthread+0xc6/0xe0
[<ffffffff8105a160>] ? kthread_create_on_node+0x1a0/0x1a0
[<ffffffff817252ac>] ? ret_from_fork+0x7c/0xb0
[<ffffffff8105a160>] ? kthread_create_on_node+0x1a0/0x1a0
sending NMI to all CPUs:
NMI backtrace for cpu 1
CPU: 1 PID: 4877 Comm: kworker/1:3 Tainted: G D 3.13.0-rc3+ #32
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
task: ffff8800da9f3b10 ti: ffff880074e46000 task.ti: ffff880074e46000
RIP: 0010:[<ffffffff8102f8e7>] [<ffffffff8102f8e7>] flat_send_IPI_mask+0x57/0x80
RSP: 0018:ffff880074e475b8 EFLAGS: 00010046
RAX: 0000000000000c00 RBX: 0000000000000c00 RCX: 0000000000000006
RDX: ffffffff81c1e140 RSI: 0000000000000002 RDI: 0000000000000300
RBP: 0000000000000096 R08: 0000000000000400 R09: 0000000000000267
R10: 0000000000000266 R11: 0000000000000006 R12: 000000000000000f
R13: 0000000000000001 R14: ffffffffffffffc8 R15: ffff8800da9f3b10
FS: 0000000000000000(0000) GS:ffff88011fc80000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 0000000000000028 CR3: 0000000057bd8000 CR4: 00000000000006e0
Stack:
0000000200000001 0000000000002710 0000000088c1cfb8 0000000088c1cfb8
ffffffff8102c9b7 ffff88011fc927c0 ffffffff8107316e ffff88011fc927c0
ffff880074e47708 0000000000000000 ffffffff817207de ffff8800da9f3b10
Call Trace:
[<ffffffff8102c9b7>] ? arch_trigger_all_cpu_backtrace+0x47/0x80
[<ffffffff8107316e>] ? do_raw_spin_lock+0x6e/0x140
[<ffffffff817207de>] ? __schedule+0x9e/0x810
[<ffffffff8107d450>] ? wake_up_klogd+0x30/0x40
[<ffffffff8171c3a5>] ? printk+0x54/0x56
[<ffffffff8103e2d9>] ? do_exit+0x909/0x9f0
[<ffffffff81005a8a>] ? oops_end+0x6a/0x90
[<ffffffff8171b805>] ? no_context+0x25e/0x26a
[<ffffffff810342ff>] ? __do_page_fault+0x2af/0x460
[<ffffffff81099deb>] ? __sprint_symbol+0x8b/0xe0
[<ffffffff812a4c06>] ? string.isra.5+0x36/0xe0
[<ffffffff812a504c>] ? symbol_string.isra.10+0x5c/0xa0
[<ffffffff81724be2>] ? page_fault+0x22/0x30
[<ffffffff8105a85c>] ? kthread_data+0xc/0x20
[<ffffffff81054d8d>] ? wq_worker_sleeping+0xd/0x80
[<ffffffff81720b3d>] ? __schedule+0x3fd/0x810
[<ffffffff812b22eb>] ? debug_object_active_state+0x12b/0x170
[<ffffffff8103d330>] ? will_become_orphaned_pgrp+0xb0/0xb0
[<ffffffff8103e072>] ? do_exit+0x6a2/0x9f0
[<ffffffff81005a8a>] ? oops_end+0x6a/0x90
[<ffffffff8171b805>] ? no_context+0x25e/0x26a
[<ffffffff810342ff>] ? __do_page_fault+0x2af/0x460
[<ffffffff8106d263>] ? idle_balance+0x193/0x1a0
[<ffffffff817243fa>] ? _raw_spin_unlock_irq+0xa/0x10
[<ffffffff81062597>] ? finish_task_switch+0x57/0xa0
[<ffffffff817209ea>] ? __schedule+0x2aa/0x810
[<ffffffff81724be2>] ? page_fault+0x22/0x30
[<ffffffffa05c8ad6>] ? zlib_uncompress+0xc6/0x190 [squashfs]
[<ffffffffa05c8a48>] ? zlib_uncompress+0x38/0x190 [squashfs]
[<ffffffffa05c83f4>] ? squashfs_decompress+0x64/0xa0 [squashfs]
[<ffffffffa05c4109>] ? squashfs_buffer_read_async+0x69/0x2e0 [squashfs]
[<ffffffff810536d5>] ? process_one_work+0x175/0x3f0
[<ffffffff81054224>] ? worker_thread+0x114/0x3a0
[<ffffffff81054110>] ? manage_workers.isra.26+0x290/0x290
[<ffffffff8105a226>] ? kthread+0xc6/0xe0
[<ffffffff8105a160>] ? kthread_create_on_node+0x1a0/0x1a0
[<ffffffff817252ac>] ? ret_from_fork+0x7c/0xb0
[<ffffffff8105a160>] ? kthread_create_on_node+0x1a0/0x1a0
Code: 25 00 b3 5f ff f6 c4 10 75 f2 44 89 e0 c1 e0 18 89 04 25 10 b3 5f ff 89 f0 09 d8 80 cf 04 83 fe 02 0f 44 c3 89 04 25 00 b3 5f ff <55> 9d 48 83 c4 08 5b 5d 41 5c c3 89 74 24 04 ff 92 50 01 00 00
NMI backtrace for cpu 2
INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run: 115.138 msecs
CPU: 2 PID: 0 Comm: swapper/2 Tainted: G D 3.13.0-rc3+ #32
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
task: ffff88011b07c1a0 ti: ffff88011b0fa000 task.ti: ffff88011b0fa000
RIP: 0010:[<ffffffff8100ae3b>] [<ffffffff8100ae3b>] default_idle+0x1b/0xa0
RSP: 0018:ffff88011b0fbf00 EFLAGS: 00000246
RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0100000000000000
RDX: 0100000000000000 RSI: 0000000000000000 RDI: ffff88011fd0d280
RBP: 0000000000000002 R08: 0000000000000000 R09: 0000000000000001
R10: 0000000000000000 R11: 0000000000000000 R12: ffff88011b0fbfd8
R13: ffff88011b0fbfd8 R14: ffffffff81cd8fd0 R15: 0000000000000000
FS: 0000000000000000(0000) GS:ffff88011fd00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: ffffffffff600400 CR3: 000000011a7e3000 CR4: 00000000000006e0
Stack:
0000000000000000 ffff88011b0fbfd8 ffffffff8107f1a1 ffff88011b0fbfd8
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
[<ffffffff8107f1a1>] ? cpu_startup_entry+0x141/0x220
Code: 9c 2d 05 00 66 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 8b 05 dd 6e cc 00 55 65 8b 2c 25 1c b0 00 00 53 85 c0 7f 17 fb f4 <8b> 05 c7 6e cc 00 65 8b 2c 25 1c b0 00 00 85 c0 7f 3b 5b 5d c3
INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run: 141.182 msecs
NMI backtrace for cpu 0
CPU: 0 PID: 0 Comm: swapper/0 Tainted: G D 3.13.0-rc3+ #32
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
task: ffffffff81c10480 ti: ffffffff81c00000 task.ti: ffffffff81c00000
RIP: 0010:[<ffffffff8100ae3b>] [<ffffffff8100ae3b>] default_idle+0x1b/0xa0
RSP: 0018:ffffffff81c01f68 EFLAGS: 00000246
RAX: 0000000000000000 RBX: ffffffffffffffff RCX: 0100000000000000
RDX: 0100000000000000 RSI: 0000000000000000 RDI: ffff88011fc0d280
RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001
R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff81c01fd8
R13: ffffffff81c01fd8 R14: ffffffff81cd8fd0 R15: 0000000000000000
FS: 0000000000000000(0000) GS:ffff88011fc00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: ffffffffff600400 CR3: 00000000daa9f000 CR4: 00000000000006f0
Stack:
ffffffffffffffff ffffffff81c01fd8 ffffffff8107f1a1 ffffffff81c01fd8
ffffffffffffffff ffffffff81d82920 ffff88011ffcd540 ffffffff81d892c0
0000000000000000 0000000000000000 ffffffff81cf4d9c ffffffff81cf4849
Call Trace:
[<ffffffff8107f1a1>] ? cpu_startup_entry+0x141/0x220
[<ffffffff81cf4d9c>] ? start_kernel+0x376/0x381
[<ffffffff81cf4849>] ? repair_env_string+0x58/0x58
Code: 9c 2d 05 00 66 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 8b 05 dd 6e cc 00 55 65 8b 2c 25 1c b0 00 00 53 85 c0 7f 17 fb f4 <8b> 05 c7 6e cc 00 65 8b 2c 25 1c b0 00 00 85 c0 7f 3b 5b 5d c3
INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run: 141.252 msecs
NMI backtrace for cpu 3
CPU: 3 PID: 0 Comm: swapper/3 Tainted: G D 3.13.0-rc3+ #32
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
task: ffff88011b07c830 ti: ffff88011b0fc000 task.ti: ffff88011b0fc000
RIP: 0010:[<ffffffff8100ae3b>] [<ffffffff8100ae3b>] default_idle+0x1b/0xa0
RSP: 0018:ffff88011b0fdf00 EFLAGS: 00000246
RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0100000000000000
RDX: 0100000000000000 RSI: 0000000000000000 RDI: ffff88011fd8d280
RBP: 0000000000000003 R08: 0000000000000000 R09: 0000000000000001
R10: 0000000000000000 R11: 0000000000000000 R12: ffff88011b0fdfd8
R13: ffff88011b0fdfd8 R14: ffffffff81cd8fd0 R15: 0000000000000000
FS: 0000000000000000(0000) GS:ffff88011fd80000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: ffffffffff600400 CR3: 00000000dbb8f000 CR4: 00000000000006e0
Stack:
0000000000000000 ffff88011b0fdfd8 ffffffff8107f1a1 ffff88011b0fdfd8
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
[<ffffffff8107f1a1>] ? cpu_startup_entry+0x141/0x220
Code: 9c 2d 05 00 66 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 8b 05 dd 6e cc 00 55 65 8b 2c 25 1c b0 00 00 53 85 c0 7f 17 fb f4 <8b> 05 c7 6e cc 00 65 8b 2c 25 1c b0 00 00 85 c0 7f 3b 5b 5d c3
hda: DMA interrupt recovery
hda: lost interrupt
hda: ide_dma_sff_timer_expiry: DMA status (0x64)
hda: DMA interrupt recovery
hda: lost interrupt
ide-atapi: cmd 0x3 timed out
hdc: lost interrupt
hda: lost interrupt
hda: lost interrupt
BUG: spinlock lockup suspected on CPU#3, syslogd/2719
lock: 0xffff88011fc927c0, .magic: dead4ead, .owner: kworker/1:3/4877, .owner_cpu: 1
CPU: 3 PID: 2719 Comm: syslogd Tainted: G D 3.13.0-rc3+ #32
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
0000000088c1cfb8 ffffffff8171e362 ffff88011fc927c0 ffffffff81073169
ffff88011b36c1a0 00000000000127c0 ffff88011fc927c0 ffffffff81065fc6
0000000000000000 ffff88011b36c1a0 0000000000000000 0000000000000000
Call Trace:
[<ffffffff8171e362>] ? dump_stack+0x41/0x51
[<ffffffff81073169>] ? do_raw_spin_lock+0x69/0x140
[<ffffffff81065fc6>] ? wake_up_new_task+0x96/0x170
[<ffffffff8103bdaf>] ? do_fork+0x12f/0x2f0
[<ffffffff81122d50>] ? __fd_install+0x20/0x50
[<ffffffff817255f9>] ? stub_clone+0x69/0x90
[<ffffffff81725352>] ? system_call_fastpath+0x16/0x1b
sending NMI to all CPUs:
NMI backtrace for cpu 3
CPU: 3 PID: 2719 Comm: syslogd Tainted: G D 3.13.0-rc3+ #32
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
task: ffff8800d9d541a0 ti: ffff8800dbb8a000 task.ti: ffff8800dbb8a000
RIP: 0010:[<ffffffff8102f8e7>] [<ffffffff8102f8e7>] flat_send_IPI_mask+0x57/0x80
RSP: 0018:ffff8800dbb8be60 EFLAGS: 00010046
RAX: 0000000000000c00 RBX: 0000000000000c00 RCX: 000000000000fefd
RDX: ffffffff81c1e140 RSI: 0000000000000002 RDI: 0000000000000300
RBP: 0000000000000086 R08: 0000000000000400 R09: 00000000000002fe
R10: 00000000000002fd R11: 0000000000000006 R12: 000000000000000f
R13: ffff88011b36c6a8 R14: 0000000000000246 R15: 0000000000001311
FS: 00007f71050c86f0(0000) GS:ffff88011fd80000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 000000000060ce00 CR3: 00000000daa9f000 CR4: 00000000000006e0
Stack:
0000000200000001 0000000000002710 0000000088c1cfb8 0000000088c1cfb8
ffffffff8102c9b7 ffff88011fc927c0 ffffffff8107316e ffff88011b36c1a0
00000000000127c0 ffff88011fc927c0 ffffffff81065fc6 0000000000000000
Call Trace:
[<ffffffff8102c9b7>] ? arch_trigger_all_cpu_backtrace+0x47/0x80
[<ffffffff8107316e>] ? do_raw_spin_lock+0x6e/0x140
[<ffffffff81065fc6>] ? wake_up_new_task+0x96/0x170
[<ffffffff8103bdaf>] ? do_fork+0x12f/0x2f0
[<ffffffff81122d50>] ? __fd_install+0x20/0x50
[<ffffffff817255f9>] ? stub_clone+0x69/0x90
[<ffffffff81725352>] ? system_call_fastpath+0x16/0x1b
Code: 25 00 b3 5f ff f6 c4 10 75 f2 44 89 e0 c1 e0 18 89 04 25 10 b3 5f ff 89 f0 09 d8 80 cf 04 83 fe 02 0f 44 c3 89 04 25 00 b3 5f ff <55> 9d 48 83 c4 08 5b 5d 41 5c c3 89 74 24 04 ff 92 50 01 00 00
NMI backtrace for cpu 1
CPU: 1 PID: 4877 Comm: kworker/1:3 Tainted: G D 3.13.0-rc3+ #32
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
task: ffff8800da9f3b10 ti: ffff880074e46000 task.ti: ffff880074e46000
RIP: 0010:[<ffffffff81073222>] [<ffffffff81073222>] do_raw_spin_lock+0x122/0x140
RSP: 0018:ffff880074e475f0 EFLAGS: 00000002
RAX: 0000000000000027 RBX: ffff88011fc927c0 RCX: 000000007beba1ad
RDX: 0000000000000028 RSI: 0000000000000001 RDI: 0000000000230471
RBP: 0000000088c1cfb8 R08: 0000000000000400 R09: 0000000000000267
R10: 0000000000000266 R11: 0000000000000006 R12: 0000000088c1cfb8
R13: 0000000000000001 R14: ffffffffffffffc8 R15: ffff8800da9f3b10
FS: 0000000000000000(0000) GS:ffff88011fc80000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 0000000000000028 CR3: 0000000057bd8000 CR4: 00000000000006e0
Stack:
ffff88011fc927c0 ffff880074e47708 0000000000000000 ffffffff817207de
ffff8800da9f3b10 ffff880074e47fd8 00000000000127c0 00000000000127c0
ffff8800da9f3b10 0000000000000000 0000000000000001 ffffffff8107d450
Call Trace:
[<ffffffff817207de>] ? __schedule+0x9e/0x810
[<ffffffff8107d450>] ? wake_up_klogd+0x30/0x40
[<ffffffff8171c3a5>] ? printk+0x54/0x56
[<ffffffff8103e2d9>] ? do_exit+0x909/0x9f0
[<ffffffff81005a8a>] ? oops_end+0x6a/0x90
[<ffffffff8171b805>] ? no_context+0x25e/0x26a
[<ffffffff810342ff>] ? __do_page_fault+0x2af/0x460
[<ffffffff81099deb>] ? __sprint_symbol+0x8b/0xe0
[<ffffffff812a4c06>] ? string.isra.5+0x36/0xe0
[<ffffffff812a504c>] ? symbol_string.isra.10+0x5c/0xa0
[<ffffffff81724be2>] ? page_fault+0x22/0x30
[<ffffffff8105a85c>] ? kthread_data+0xc/0x20
[<ffffffff81054d8d>] ? wq_worker_sleeping+0xd/0x80
[<ffffffff81720b3d>] ? __schedule+0x3fd/0x810
[<ffffffff812b22eb>] ? debug_object_active_state+0x12b/0x170
[<ffffffff8103d330>] ? will_become_orphaned_pgrp+0xb0/0xb0
[<ffffffff8103e072>] ? do_exit+0x6a2/0x9f0
[<ffffffff81005a8a>] ? oops_end+0x6a/0x90
[<ffffffff8171b805>] ? no_context+0x25e/0x26a
[<ffffffff810342ff>] ? __do_page_fault+0x2af/0x460
[<ffffffff8106d263>] ? idle_balance+0x193/0x1a0
[<ffffffff817243fa>] ? _raw_spin_unlock_irq+0xa/0x10
[<ffffffff81062597>] ? finish_task_switch+0x57/0xa0
[<ffffffff817209ea>] ? __schedule+0x2aa/0x810
[<ffffffff81724be2>] ? page_fault+0x22/0x30
[<ffffffffa05c8ad6>] ? zlib_uncompress+0xc6/0x190 [squashfs]
[<ffffffffa05c8a48>] ? zlib_uncompress+0x38/0x190 [squashfs]
[<ffffffffa05c83f4>] ? squashfs_decompress+0x64/0xa0 [squashfs]
[<ffffffffa05c4109>] ? squashfs_buffer_read_async+0x69/0x2e0 [squashfs]
[<ffffffff810536d5>] ? process_one_work+0x175/0x3f0
[<ffffffff81054224>] ? worker_thread+0x114/0x3a0
[<ffffffff81054110>] ? manage_workers.isra.26+0x290/0x290
[<ffffffff8105a226>] ? kthread+0xc6/0xe0
[<ffffffff8105a160>] ? kthread_create_on_node+0x1a0/0x1a0
[<ffffffff817252ac>] ? ret_from_fork+0x7c/0xb0
[<ffffffff8105a160>] ? kthread_create_on_node+0x1a0/0x1a0
Code: 00 e9 40 ff ff ff 48 c7 c6 ae 72 9a 81 48 89 df e8 08 90 6a 00 e9 1b ff ff ff 48 c7 c6 cd 1c 97 81 e8 f7 8f 6a 00 e9 f7 fe ff ff <0f> b6 03 38 c2 0f 84 56 ff ff ff f3 90 90 eb f0 66 66 66 66 66
NMI backtrace for cpu 2
INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run: 160.716 msecs
CPU: 2 PID: 0 Comm: swapper/2 Tainted: G D 3.13.0-rc3+ #32
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
task: ffff88011b07c1a0 ti: ffff88011b0fa000 task.ti: ffff88011b0fa000
RIP: 0010:[<ffffffff8100ae3b>] [<ffffffff8100ae3b>] default_idle+0x1b/0xa0
RSP: 0018:ffff88011b0fbf00 EFLAGS: 00000246
RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0100000000000000
RDX: 0100000000000000 RSI: 0000000000000000 RDI: ffff88011fd0d280
RBP: 0000000000000002 R08: 0000000000000000 R09: 0000000000000001
R10: 0000000000000000 R11: 0000000000000000 R12: ffff88011b0fbfd8
R13: ffff88011b0fbfd8 R14: ffffffff81cd8fd0 R15: 0000000000000000
FS: 0000000000000000(0000) GS:ffff88011fd00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: ffffffffff600400 CR3: 00000000db23b000 CR4: 00000000000006e0
Stack:
0000000000000000 ffff88011b0fbfd8 ffffffff8107f1a1 ffff88011b0fbfd8
0000000000000000 0000000000000000 0000000000000000 0000000000000000
0000000000000000 0000000000000000 0000000000000000 0000000000000000
Call Trace:
[<ffffffff8107f1a1>] ? cpu_startup_entry+0x141/0x220
Code: 9c 2d 05 00 66 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 8b 05 dd 6e cc 00 55 65 8b 2c 25 1c b0 00 00 53 85 c0 7f 17 fb f4 <8b> 05 c7 6e cc 00 65 8b 2c 25 1c b0 00 00 85 c0 7f 3b 5b 5d c3
INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run: 202.778 msecs
NMI backtrace for cpu 0
CPU: 0 PID: 0 Comm: swapper/0 Tainted: G D 3.13.0-rc3+ #32
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
task: ffffffff81c10480 ti: ffffffff81c00000 task.ti: ffffffff81c00000
RIP: 0010:[<ffffffff8100ae3b>] [<ffffffff8100ae3b>] default_idle+0x1b/0xa0
RSP: 0018:ffffffff81c01f68 EFLAGS: 00000246
RAX: 0000000000000000 RBX: ffffffffffffffff RCX: 0100000000000000
RDX: 0100000000000000 RSI: 0000000000000000 RDI: ffff88011fc0d280
R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff81c01fd8
R13: ffffffff81c01fd8 R14: ffffffff81cd8fd0 R15: 0000000000000000
FS: 0000000000000000(0000) GS:ffff88011fc00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 0000000000608060 CR3: 0000000031f37000 CR4: 00000000000006f0
Stack:
ffffffffffffffff ffffffff81c01fd8 ffffffff8107f1a1 ffffffff81c01fd8
ffffffffffffffff ffffffff81d82920 ffff88011ffcd540 ffffffff81d892c0
0000000000000000 0000000000000000 ffffffff81cf4d9c ffffffff81cf4849
Call Trace:
[<ffffffff8107f1a1>] ? cpu_startup_entry+0x141/0x220
[<ffffffff81cf4d9c>] ? start_kernel+0x376/0x381
[<ffffffff81cf4849>] ? repair_env_string+0x58/0x58
Code: 9c 2d 05 00 66 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 8b 05 dd 6e cc 00 55 65 8b 2c 25 1c b0 00 00 53 85 c0 7f 17 fb f4 <8b> 05 c7 6e cc 00 65 8b 2c 25 1c b0 00 00 85 c0 7f 3b 5b 5d c3
qemu: terminating on signal 15 from pid 7695
*****************************************************************
To summarise, I am entirely unconvinced about the merits of
adding the asynchronous patch. Two last points need to be made here:
1. Squashfs's readpage() is fairly unique and unusual, in that it
does readahead itself and adds multiple pages to the page cache in
one call, this is obviously because Squashfs blocks tend to be much
larger than the page size. Conversely, most other filesystems
readpage() routines add the page it has been called to read and
that is it. As such making Squashfs readpage() asynchronous
offers the real risk of introducing page races within code that
does not exist with the synchronous Squashfs readpage() implementation
or with other filesystem's asynchronous readpage() implementations.
The fact that the asynchronous Squashfs readpage() implementation
shows worse performance than the synchronous readpage() implementation
when multiple asynchronous readpage() calls do not take place, and
generates kernel oopses when multiple asynchronous readpage()
calls do take place, shows that the above fears are borne out.
2. An observation which may not be immediately obvious.
Let's look again at the performance results, specifically the best
results for the asynchronous patch where it outperforms
the synchronous readpage().
Squashfs: gzip filesystem 128K blocks
Asyn No Asyn Asyn No Asyn Asyn No Asyn
Single Single Multi Multi Percpu Percpu
-------------------------------------------------------
32K: 42.9 47.2 43.0 46.1 42.9 47.1
64K: 50.7 47.0 55.1 53.1 55.2 49.6
128K: 51.1 47.6 54.9 49.2 55.7 48.7
256K: 51.0 49.5 54.7 48.2 57.3 49.3
512K: 53.6 48.2 55.2 47.6 54.9 48.3
1024K: 51.1 47.9 54.7 47.5 54.6 46.5
Now compare them against the performance results for 256K block filesystems.
Squashfs: gzip filesystem 256K blocks
Asyn No Asyn Asyn No Asyn Asyn No Asyn
Single Single Multi Multi Percpu Percpu
-------------------------------------------------------
32K: 54.0 95.9 53.8 98.7 53.9 85.3
64K: 53.7 86.9 53.4 103 53.4 86.3
128K: 53.2 94.4 53.6 100 53.7 97.9
256K: 55.5 101 53.0 94.1 53.3 87.0
512K: 53.1 93.0 53.4 87.7 53.2 89.8
1024K: 53.2 91.4 52.7 91.3 53.0 95.4
So you're using a 128K block filesystem and add asynchronous readpage
to gain a 16% improvement. A somewhat better approach would be to
move to a 256K block filesystem, and gain a 74% performance boost.
Phillip
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists