* Re: jbd2: don't wake kjournald unnecessarily
@ 2013-01-19 23:44 Sedat Dilek
2013-01-20 0:06 ` Sedat Dilek
0 siblings, 1 reply; 26+ messages in thread
From: Sedat Dilek @ 2013-01-19 23:44 UTC (permalink / raw)
To: Eric Sandeen
Cc: Jan Kara, linux-fsdevel, Ext4 Developers List, Theodore Ts'o,
LKML, linux-next
[-- Attachment #1: Type: text/plain, Size: 2415 bytes --]
Hi,
I and some others hit a similiar problem in Linux-Next
(next-20130118), please see [1] and [2].
[3] has a interim analyze of my problems.
After suspecting the problem was caused by TTY-NEXT, it turned out to
be a JBD2 problem finally.
The freezer/pm_test was helpful to hit the issue (Thanks Rafael for the hint!).
So, the issue has two faces: TTY and JBD2.
[4] gives a list and URLs of the patches I had to apply to have a
clean system again.
After applying the two TTY patches (without Eric's JBD2-fix!) the
call-trace after freezer/pm_test looked like this;
[ 433.527986] PM: Syncing filesystems ... done.
[ 433.843761] PM: Preparing system for mem sleep
[ 436.306002] Freezing user space processes ...
[ 456.304956] Freezing of tasks failed after 20.01 seconds (1 tasks
refusing to freeze, wq_busy=0):
[ 456.305060] Cache I/O D ffffffff8180d780 0 2132 1 0x00000004
[ 456.305065] ffff88007b9dfe18 0000000000000046 ffff88007b9dfdc8
0000000300000001
[ 456.305069] ffff880097e21720 ffff88007b9dffd8 ffff88007b9dffd8
ffff88007b9dffd8
[ 456.305072] ffff880119b32e40 ffff880097e21720 ffff88007b9dfe28
ffff880118077800
[ 456.305076] Call Trace:
[ 456.305085] [<ffffffff816b7469>] schedule+0x29/0x70
[ 456.305089] [<ffffffff8129067d>] jbd2_log_wait_commit+0xcd/0x1a0
[ 456.305094] [<ffffffff8107eac0>] ? add_wait_queue+0x60/0x60
[ 456.305098] [<ffffffff812307a5>] ext4_sync_file+0x205/0x380
[ 456.305103] [<ffffffff811c43ad>] do_fsync+0x5d/0x90
[ 456.305108] [<ffffffff8119442b>] ? sys_write+0x6b/0xa0
[ 456.305111] [<ffffffff811c4790>] sys_fsync+0x10/0x20
[ 456.305114] [<ffffffff816c0edd>] system_call_fastpath+0x1a/0x1f
[ 456.305122]
[ 456.305124] Restarting tasks ... done.
[ 456.315056] video LNXVIDEO:00: Restoring backlight state
After applying Eric's patch [5], I could not hit the call-trace again.
NOTE: The patch is from December 2012 and is not shipped in latest Linux-Next.
The attached testcase script was helpful to force the call-trace.
I have run 50 loops of it w/o an issue!
Feel free to add a Reported-by/Tested-by.
( The issue kept me busy for the last days. )
Regards,
- Sedat -
[1] http://marc.info/?t=135283664600002&r=1&w=2
[2] http://marc.info/?t=135862023700004&r=1&w=2
[3] http://marc.info/?l=linux-kernel&m=135862010419101&w=2
[4] http://marc.info/?l=linux-next&m=135863550923093&w=2
[5] http://patchwork.ozlabs.org/patch/207237/
[-- Attachment #2: run_pm-test_v2.sh --]
[-- Type: application/x-sh, Size: 875 bytes --]
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-19 23:44 jbd2: don't wake kjournald unnecessarily Sedat Dilek
@ 2013-01-20 0:06 ` Sedat Dilek
2013-01-20 0:35 ` Sedat Dilek
2013-01-21 10:47 ` Jan Kara
0 siblings, 2 replies; 26+ messages in thread
From: Sedat Dilek @ 2013-01-20 0:06 UTC (permalink / raw)
To: Eric Sandeen
Cc: Jan Kara, linux-fsdevel, Ext4 Developers List, Theodore Ts'o,
LKML, linux-next
On Sun, Jan 20, 2013 at 12:44 AM, Sedat Dilek <sedat.dilek@gmail.com> wrote:
> Hi,
>
> I and some others hit a similiar problem in Linux-Next
> (next-20130118), please see [1] and [2].
>
> [3] has a interim analyze of my problems.
>
> After suspecting the problem was caused by TTY-NEXT, it turned out to
> be a JBD2 problem finally.
> The freezer/pm_test was helpful to hit the issue (Thanks Rafael for the hint!).
>
> So, the issue has two faces: TTY and JBD2.
> [4] gives a list and URLs of the patches I had to apply to have a
> clean system again.
>
> After applying the two TTY patches (without Eric's JBD2-fix!) the
> call-trace after freezer/pm_test looked like this;
>
> [ 433.527986] PM: Syncing filesystems ... done.
> [ 433.843761] PM: Preparing system for mem sleep
> [ 436.306002] Freezing user space processes ...
> [ 456.304956] Freezing of tasks failed after 20.01 seconds (1 tasks
> refusing to freeze, wq_busy=0):
> [ 456.305060] Cache I/O D ffffffff8180d780 0 2132 1 0x00000004
> [ 456.305065] ffff88007b9dfe18 0000000000000046 ffff88007b9dfdc8
> 0000000300000001
> [ 456.305069] ffff880097e21720 ffff88007b9dffd8 ffff88007b9dffd8
> ffff88007b9dffd8
> [ 456.305072] ffff880119b32e40 ffff880097e21720 ffff88007b9dfe28
> ffff880118077800
> [ 456.305076] Call Trace:
> [ 456.305085] [<ffffffff816b7469>] schedule+0x29/0x70
> [ 456.305089] [<ffffffff8129067d>] jbd2_log_wait_commit+0xcd/0x1a0
> [ 456.305094] [<ffffffff8107eac0>] ? add_wait_queue+0x60/0x60
> [ 456.305098] [<ffffffff812307a5>] ext4_sync_file+0x205/0x380
> [ 456.305103] [<ffffffff811c43ad>] do_fsync+0x5d/0x90
> [ 456.305108] [<ffffffff8119442b>] ? sys_write+0x6b/0xa0
> [ 456.305111] [<ffffffff811c4790>] sys_fsync+0x10/0x20
> [ 456.305114] [<ffffffff816c0edd>] system_call_fastpath+0x1a/0x1f
> [ 456.305122]
> [ 456.305124] Restarting tasks ... done.
> [ 456.315056] video LNXVIDEO:00: Restoring backlight state
>
> After applying Eric's patch [5], I could not hit the call-trace again.
> NOTE: The patch is from December 2012 and is not shipped in latest Linux-Next.
>
> The attached testcase script was helpful to force the call-trace.
> I have run 50 loops of it w/o an issue!
>
> Feel free to add a Reported-by/Tested-by.
> ( The issue kept me busy for the last days. )
>
> Regards,
> - Sedat -
>
> [1] http://marc.info/?t=135283664600002&r=1&w=2
> [2] http://marc.info/?t=135862023700004&r=1&w=2
> [3] http://marc.info/?l=linux-kernel&m=135862010419101&w=2
> [4] http://marc.info/?l=linux-next&m=135863550923093&w=2
> [5] http://patchwork.ozlabs.org/patch/207237/
Hi all,
this is really ugly... I could cry!
GRRR, I have hit the original issue again while running my testcase script!
[ 363.831226] PM: Syncing filesystems ... done.
[ 363.988855] PM: Preparing system for mem sleep
[ 369.032965] Freezing user space processes ... (elapsed 0.11 seconds) done.
[ 369.145792] Freezing remaining freezable tasks ...
[ 389.137643] Freezing of tasks failed after 20.01 seconds (1 tasks
refusing to freeze, wq_busy=0):
[ 389.137760] jbd2/loop0-8 D ffffffff8180d780 0 295 2 0x00000000
[ 389.137769] ffff8801181dfb68 0000000000000046 ffff880117de5c80
0000000000000001
[ 389.137778] ffff880117de5c80 ffff8801181dffd8 ffff8801181dffd8
ffff8801181dffd8
[ 389.137784] ffffffff81c15440 ffff880117de5c80 ffff8801181dfb68
ffff88011fa14738
[ 389.137791] Call Trace:
[ 389.137810] [<ffffffff811c6830>] ? __wait_on_buffer+0x30/0x30
[ 389.137819] [<ffffffff816b7479>] schedule+0x29/0x70
[ 389.137825] [<ffffffff816b754f>] io_schedule+0x8f/0xd0
[ 389.137832] [<ffffffff811c683e>] sleep_on_buffer+0xe/0x20
[ 389.137842] [<ffffffff816b5d4f>] __wait_on_bit+0x5f/0x90
[ 389.137849] [<ffffffff811c5ef1>] ? submit_bh+0x121/0x1e0
[ 389.137856] [<ffffffff811c6830>] ? __wait_on_buffer+0x30/0x30
[ 389.137864] [<ffffffff816b5dfc>] out_of_line_wait_on_bit+0x7c/0x90
[ 389.137873] [<ffffffff8107eb00>] ? autoremove_wake_function+0x40/0x40
[ 389.137879] [<ffffffff811c682e>] __wait_on_buffer+0x2e/0x30
[ 389.137891] [<ffffffff8128c02c>]
jbd2_journal_commit_transaction+0x18cc/0x1d60
[ 389.137899] [<ffffffff816b860e>] ? _raw_spin_lock_irqsave+0x2e/0x40
[ 389.137908] [<ffffffff81069fbf>] ? try_to_del_timer_sync+0x4f/0x70
[ 389.137915] [<ffffffff81290836>] kjournald2+0xd6/0x3e0
[ 389.137921] [<ffffffff8107eac0>] ? add_wait_queue+0x60/0x60
[ 389.137926] [<ffffffff81290760>] ? commit_timeout+0x10/0x10
[ 389.137932] [<ffffffff8107ded0>] kthread+0xc0/0xd0
[ 389.137939] [<ffffffff8107de10>] ? flush_kthread_worker+0xb0/0xb0
[ 389.137946] [<ffffffff816c0e2c>] ret_from_fork+0x7c/0xb0
[ 389.137951] [<ffffffff8107de10>] ? flush_kthread_worker+0xb0/0xb0
[ 389.138017]
[ 389.138021] Restarting kernel threads ... done.
[ 389.138173] Restarting tasks ... done.
[ 389.147980] video LNXVIDEO:00: Restoring backlight state
I suspect there are still issues in JBD2 (BTW I run here EXT4FS).
[ 389.137643] Freezing of tasks failed after 20.01 seconds (1 tasks
refusing to freeze, wq_busy=0):
[ 389.137760] jbd2/loop0-8 D ffffffff8180d780 0 295 2 0x00000000
Have a good night, /me -> watching TV!
- Sedat -
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-20 0:06 ` Sedat Dilek
@ 2013-01-20 0:35 ` Sedat Dilek
2013-01-20 0:55 ` Sedat Dilek
2013-01-21 10:47 ` Jan Kara
1 sibling, 1 reply; 26+ messages in thread
From: Sedat Dilek @ 2013-01-20 0:35 UTC (permalink / raw)
To: Eric Sandeen
Cc: Jan Kara, linux-fsdevel, Ext4 Developers List, Theodore Ts'o,
LKML, linux-next
On Sun, Jan 20, 2013 at 1:06 AM, Sedat Dilek <sedat.dilek@gmail.com> wrote:
> On Sun, Jan 20, 2013 at 12:44 AM, Sedat Dilek <sedat.dilek@gmail.com> wrote:
>> Hi,
>>
>> I and some others hit a similiar problem in Linux-Next
>> (next-20130118), please see [1] and [2].
>>
>> [3] has a interim analyze of my problems.
>>
>> After suspecting the problem was caused by TTY-NEXT, it turned out to
>> be a JBD2 problem finally.
>> The freezer/pm_test was helpful to hit the issue (Thanks Rafael for the hint!).
>>
>> So, the issue has two faces: TTY and JBD2.
>> [4] gives a list and URLs of the patches I had to apply to have a
>> clean system again.
>>
>> After applying the two TTY patches (without Eric's JBD2-fix!) the
>> call-trace after freezer/pm_test looked like this;
>>
>> [ 433.527986] PM: Syncing filesystems ... done.
>> [ 433.843761] PM: Preparing system for mem sleep
>> [ 436.306002] Freezing user space processes ...
>> [ 456.304956] Freezing of tasks failed after 20.01 seconds (1 tasks
>> refusing to freeze, wq_busy=0):
>> [ 456.305060] Cache I/O D ffffffff8180d780 0 2132 1 0x00000004
>> [ 456.305065] ffff88007b9dfe18 0000000000000046 ffff88007b9dfdc8
>> 0000000300000001
>> [ 456.305069] ffff880097e21720 ffff88007b9dffd8 ffff88007b9dffd8
>> ffff88007b9dffd8
>> [ 456.305072] ffff880119b32e40 ffff880097e21720 ffff88007b9dfe28
>> ffff880118077800
>> [ 456.305076] Call Trace:
>> [ 456.305085] [<ffffffff816b7469>] schedule+0x29/0x70
>> [ 456.305089] [<ffffffff8129067d>] jbd2_log_wait_commit+0xcd/0x1a0
>> [ 456.305094] [<ffffffff8107eac0>] ? add_wait_queue+0x60/0x60
>> [ 456.305098] [<ffffffff812307a5>] ext4_sync_file+0x205/0x380
>> [ 456.305103] [<ffffffff811c43ad>] do_fsync+0x5d/0x90
>> [ 456.305108] [<ffffffff8119442b>] ? sys_write+0x6b/0xa0
>> [ 456.305111] [<ffffffff811c4790>] sys_fsync+0x10/0x20
>> [ 456.305114] [<ffffffff816c0edd>] system_call_fastpath+0x1a/0x1f
>> [ 456.305122]
>> [ 456.305124] Restarting tasks ... done.
>> [ 456.315056] video LNXVIDEO:00: Restoring backlight state
>>
>> After applying Eric's patch [5], I could not hit the call-trace again.
>> NOTE: The patch is from December 2012 and is not shipped in latest Linux-Next.
>>
>> The attached testcase script was helpful to force the call-trace.
>> I have run 50 loops of it w/o an issue!
>>
>> Feel free to add a Reported-by/Tested-by.
>> ( The issue kept me busy for the last days. )
>>
>> Regards,
>> - Sedat -
>>
>> [1] http://marc.info/?t=135283664600002&r=1&w=2
>> [2] http://marc.info/?t=135862023700004&r=1&w=2
>> [3] http://marc.info/?l=linux-kernel&m=135862010419101&w=2
>> [4] http://marc.info/?l=linux-next&m=135863550923093&w=2
>> [5] http://patchwork.ozlabs.org/patch/207237/
>
> Hi all,
>
> this is really ugly... I could cry!
>
> GRRR, I have hit the original issue again while running my testcase script!
>
> [ 363.831226] PM: Syncing filesystems ... done.
> [ 363.988855] PM: Preparing system for mem sleep
> [ 369.032965] Freezing user space processes ... (elapsed 0.11 seconds) done.
> [ 369.145792] Freezing remaining freezable tasks ...
> [ 389.137643] Freezing of tasks failed after 20.01 seconds (1 tasks
> refusing to freeze, wq_busy=0):
> [ 389.137760] jbd2/loop0-8 D ffffffff8180d780 0 295 2 0x00000000
> [ 389.137769] ffff8801181dfb68 0000000000000046 ffff880117de5c80
> 0000000000000001
> [ 389.137778] ffff880117de5c80 ffff8801181dffd8 ffff8801181dffd8
> ffff8801181dffd8
> [ 389.137784] ffffffff81c15440 ffff880117de5c80 ffff8801181dfb68
> ffff88011fa14738
> [ 389.137791] Call Trace:
> [ 389.137810] [<ffffffff811c6830>] ? __wait_on_buffer+0x30/0x30
> [ 389.137819] [<ffffffff816b7479>] schedule+0x29/0x70
> [ 389.137825] [<ffffffff816b754f>] io_schedule+0x8f/0xd0
> [ 389.137832] [<ffffffff811c683e>] sleep_on_buffer+0xe/0x20
> [ 389.137842] [<ffffffff816b5d4f>] __wait_on_bit+0x5f/0x90
> [ 389.137849] [<ffffffff811c5ef1>] ? submit_bh+0x121/0x1e0
> [ 389.137856] [<ffffffff811c6830>] ? __wait_on_buffer+0x30/0x30
> [ 389.137864] [<ffffffff816b5dfc>] out_of_line_wait_on_bit+0x7c/0x90
> [ 389.137873] [<ffffffff8107eb00>] ? autoremove_wake_function+0x40/0x40
> [ 389.137879] [<ffffffff811c682e>] __wait_on_buffer+0x2e/0x30
> [ 389.137891] [<ffffffff8128c02c>]
> jbd2_journal_commit_transaction+0x18cc/0x1d60
> [ 389.137899] [<ffffffff816b860e>] ? _raw_spin_lock_irqsave+0x2e/0x40
> [ 389.137908] [<ffffffff81069fbf>] ? try_to_del_timer_sync+0x4f/0x70
> [ 389.137915] [<ffffffff81290836>] kjournald2+0xd6/0x3e0
> [ 389.137921] [<ffffffff8107eac0>] ? add_wait_queue+0x60/0x60
> [ 389.137926] [<ffffffff81290760>] ? commit_timeout+0x10/0x10
> [ 389.137932] [<ffffffff8107ded0>] kthread+0xc0/0xd0
> [ 389.137939] [<ffffffff8107de10>] ? flush_kthread_worker+0xb0/0xb0
> [ 389.137946] [<ffffffff816c0e2c>] ret_from_fork+0x7c/0xb0
> [ 389.137951] [<ffffffff8107de10>] ? flush_kthread_worker+0xb0/0xb0
> [ 389.138017]
> [ 389.138021] Restarting kernel threads ... done.
> [ 389.138173] Restarting tasks ... done.
> [ 389.147980] video LNXVIDEO:00: Restoring backlight state
>
> I suspect there are still issues in JBD2 (BTW I run here EXT4FS).
>
> [ 389.137643] Freezing of tasks failed after 20.01 seconds (1 tasks
> refusing to freeze, wq_busy=0):
> [ 389.137760] jbd2/loop0-8 D ffffffff8180d780 0 295 2 0x00000000
>
> Have a good night, /me -> watching TV!
>
> - Sedat -
Man, what a NONSENSE I am telling...
The mentioned so-called fix is already in next-20130118, shame on me!
commit 7e2fb2d7e6a3094473f101ae33dd6431ae6d2ed1
"jbd: don't wake kjournald unnecessarily"
- Sedat -
[1] http://git.kernel.org/?p=linux/kernel/git/next/linux-next.git;a=commitdiff;h=7e2fb2d7e6a3094473f101ae33dd6431ae6d2ed1
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-20 0:35 ` Sedat Dilek
@ 2013-01-20 0:55 ` Sedat Dilek
0 siblings, 0 replies; 26+ messages in thread
From: Sedat Dilek @ 2013-01-20 0:55 UTC (permalink / raw)
To: Eric Sandeen
Cc: Jan Kara, linux-fsdevel, Ext4 Developers List, Theodore Ts'o,
LKML, linux-next
On Sun, Jan 20, 2013 at 1:35 AM, Sedat Dilek <sedat.dilek@gmail.com> wrote:
> On Sun, Jan 20, 2013 at 1:06 AM, Sedat Dilek <sedat.dilek@gmail.com> wrote:
>> On Sun, Jan 20, 2013 at 12:44 AM, Sedat Dilek <sedat.dilek@gmail.com> wrote:
>>> Hi,
>>>
>>> I and some others hit a similiar problem in Linux-Next
>>> (next-20130118), please see [1] and [2].
>>>
>>> [3] has a interim analyze of my problems.
>>>
>>> After suspecting the problem was caused by TTY-NEXT, it turned out to
>>> be a JBD2 problem finally.
>>> The freezer/pm_test was helpful to hit the issue (Thanks Rafael for the hint!).
>>>
>>> So, the issue has two faces: TTY and JBD2.
>>> [4] gives a list and URLs of the patches I had to apply to have a
>>> clean system again.
>>>
>>> After applying the two TTY patches (without Eric's JBD2-fix!) the
>>> call-trace after freezer/pm_test looked like this;
>>>
>>> [ 433.527986] PM: Syncing filesystems ... done.
>>> [ 433.843761] PM: Preparing system for mem sleep
>>> [ 436.306002] Freezing user space processes ...
>>> [ 456.304956] Freezing of tasks failed after 20.01 seconds (1 tasks
>>> refusing to freeze, wq_busy=0):
>>> [ 456.305060] Cache I/O D ffffffff8180d780 0 2132 1 0x00000004
>>> [ 456.305065] ffff88007b9dfe18 0000000000000046 ffff88007b9dfdc8
>>> 0000000300000001
>>> [ 456.305069] ffff880097e21720 ffff88007b9dffd8 ffff88007b9dffd8
>>> ffff88007b9dffd8
>>> [ 456.305072] ffff880119b32e40 ffff880097e21720 ffff88007b9dfe28
>>> ffff880118077800
>>> [ 456.305076] Call Trace:
>>> [ 456.305085] [<ffffffff816b7469>] schedule+0x29/0x70
>>> [ 456.305089] [<ffffffff8129067d>] jbd2_log_wait_commit+0xcd/0x1a0
>>> [ 456.305094] [<ffffffff8107eac0>] ? add_wait_queue+0x60/0x60
>>> [ 456.305098] [<ffffffff812307a5>] ext4_sync_file+0x205/0x380
>>> [ 456.305103] [<ffffffff811c43ad>] do_fsync+0x5d/0x90
>>> [ 456.305108] [<ffffffff8119442b>] ? sys_write+0x6b/0xa0
>>> [ 456.305111] [<ffffffff811c4790>] sys_fsync+0x10/0x20
>>> [ 456.305114] [<ffffffff816c0edd>] system_call_fastpath+0x1a/0x1f
>>> [ 456.305122]
>>> [ 456.305124] Restarting tasks ... done.
>>> [ 456.315056] video LNXVIDEO:00: Restoring backlight state
>>>
>>> After applying Eric's patch [5], I could not hit the call-trace again.
>>> NOTE: The patch is from December 2012 and is not shipped in latest Linux-Next.
>>>
>>> The attached testcase script was helpful to force the call-trace.
>>> I have run 50 loops of it w/o an issue!
>>>
>>> Feel free to add a Reported-by/Tested-by.
>>> ( The issue kept me busy for the last days. )
>>>
>>> Regards,
>>> - Sedat -
>>>
>>> [1] http://marc.info/?t=135283664600002&r=1&w=2
>>> [2] http://marc.info/?t=135862023700004&r=1&w=2
>>> [3] http://marc.info/?l=linux-kernel&m=135862010419101&w=2
>>> [4] http://marc.info/?l=linux-next&m=135863550923093&w=2
>>> [5] http://patchwork.ozlabs.org/patch/207237/
>>
>> Hi all,
>>
>> this is really ugly... I could cry!
>>
>> GRRR, I have hit the original issue again while running my testcase script!
>>
>> [ 363.831226] PM: Syncing filesystems ... done.
>> [ 363.988855] PM: Preparing system for mem sleep
>> [ 369.032965] Freezing user space processes ... (elapsed 0.11 seconds) done.
>> [ 369.145792] Freezing remaining freezable tasks ...
>> [ 389.137643] Freezing of tasks failed after 20.01 seconds (1 tasks
>> refusing to freeze, wq_busy=0):
>> [ 389.137760] jbd2/loop0-8 D ffffffff8180d780 0 295 2 0x00000000
>> [ 389.137769] ffff8801181dfb68 0000000000000046 ffff880117de5c80
>> 0000000000000001
>> [ 389.137778] ffff880117de5c80 ffff8801181dffd8 ffff8801181dffd8
>> ffff8801181dffd8
>> [ 389.137784] ffffffff81c15440 ffff880117de5c80 ffff8801181dfb68
>> ffff88011fa14738
>> [ 389.137791] Call Trace:
>> [ 389.137810] [<ffffffff811c6830>] ? __wait_on_buffer+0x30/0x30
>> [ 389.137819] [<ffffffff816b7479>] schedule+0x29/0x70
>> [ 389.137825] [<ffffffff816b754f>] io_schedule+0x8f/0xd0
>> [ 389.137832] [<ffffffff811c683e>] sleep_on_buffer+0xe/0x20
>> [ 389.137842] [<ffffffff816b5d4f>] __wait_on_bit+0x5f/0x90
>> [ 389.137849] [<ffffffff811c5ef1>] ? submit_bh+0x121/0x1e0
>> [ 389.137856] [<ffffffff811c6830>] ? __wait_on_buffer+0x30/0x30
>> [ 389.137864] [<ffffffff816b5dfc>] out_of_line_wait_on_bit+0x7c/0x90
>> [ 389.137873] [<ffffffff8107eb00>] ? autoremove_wake_function+0x40/0x40
>> [ 389.137879] [<ffffffff811c682e>] __wait_on_buffer+0x2e/0x30
>> [ 389.137891] [<ffffffff8128c02c>]
>> jbd2_journal_commit_transaction+0x18cc/0x1d60
>> [ 389.137899] [<ffffffff816b860e>] ? _raw_spin_lock_irqsave+0x2e/0x40
>> [ 389.137908] [<ffffffff81069fbf>] ? try_to_del_timer_sync+0x4f/0x70
>> [ 389.137915] [<ffffffff81290836>] kjournald2+0xd6/0x3e0
>> [ 389.137921] [<ffffffff8107eac0>] ? add_wait_queue+0x60/0x60
>> [ 389.137926] [<ffffffff81290760>] ? commit_timeout+0x10/0x10
>> [ 389.137932] [<ffffffff8107ded0>] kthread+0xc0/0xd0
>> [ 389.137939] [<ffffffff8107de10>] ? flush_kthread_worker+0xb0/0xb0
>> [ 389.137946] [<ffffffff816c0e2c>] ret_from_fork+0x7c/0xb0
>> [ 389.137951] [<ffffffff8107de10>] ? flush_kthread_worker+0xb0/0xb0
>> [ 389.138017]
>> [ 389.138021] Restarting kernel threads ... done.
>> [ 389.138173] Restarting tasks ... done.
>> [ 389.147980] video LNXVIDEO:00: Restoring backlight state
>>
>> I suspect there are still issues in JBD2 (BTW I run here EXT4FS).
>>
>> [ 389.137643] Freezing of tasks failed after 20.01 seconds (1 tasks
>> refusing to freeze, wq_busy=0):
>> [ 389.137760] jbd2/loop0-8 D ffffffff8180d780 0 295 2 0x00000000
>>
>> Have a good night, /me -> watching TV!
>>
>> - Sedat -
>
> Man, what a NONSENSE I am telling...
> The mentioned so-called fix is already in next-20130118, shame on me!
>
> commit 7e2fb2d7e6a3094473f101ae33dd6431ae6d2ed1
> "jbd: don't wake kjournald unnecessarily"
>
GNARF, SMASH... that's for JBD.
So Eric's JBD2-fix is really NOT in Linux-Next.
More sleep!
- Sedat -
> - Sedat -
>
> [1] http://git.kernel.org/?p=linux/kernel/git/next/linux-next.git;a=commitdiff;h=7e2fb2d7e6a3094473f101ae33dd6431ae6d2ed1
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-20 0:06 ` Sedat Dilek
2013-01-20 0:35 ` Sedat Dilek
@ 2013-01-21 10:47 ` Jan Kara
2013-01-21 11:40 ` Sedat Dilek
2013-01-21 12:02 ` Carlos Maiolino
1 sibling, 2 replies; 26+ messages in thread
From: Jan Kara @ 2013-01-21 10:47 UTC (permalink / raw)
To: Sedat Dilek
Cc: Eric Sandeen, Jan Kara, linux-fsdevel, Ext4 Developers List,
Theodore Ts'o, LKML, linux-next
On Sun 20-01-13 01:06:40, Sedat Dilek wrote:
> On Sun, Jan 20, 2013 at 12:44 AM, Sedat Dilek <sedat.dilek@gmail.com> wrote:
> > Hi,
> >
> > I and some others hit a similiar problem in Linux-Next
> > (next-20130118), please see [1] and [2].
> >
> > [3] has a interim analyze of my problems.
> >
> > After suspecting the problem was caused by TTY-NEXT, it turned out to
> > be a JBD2 problem finally.
> > The freezer/pm_test was helpful to hit the issue (Thanks Rafael for the hint!).
> >
> > So, the issue has two faces: TTY and JBD2.
> > [4] gives a list and URLs of the patches I had to apply to have a
> > clean system again.
> >
> > After applying the two TTY patches (without Eric's JBD2-fix!) the
> > call-trace after freezer/pm_test looked like this;
> >
> > [ 433.527986] PM: Syncing filesystems ... done.
> > [ 433.843761] PM: Preparing system for mem sleep
> > [ 436.306002] Freezing user space processes ...
> > [ 456.304956] Freezing of tasks failed after 20.01 seconds (1 tasks
> > refusing to freeze, wq_busy=0):
> > [ 456.305060] Cache I/O D ffffffff8180d780 0 2132 1 0x00000004
> > [ 456.305065] ffff88007b9dfe18 0000000000000046 ffff88007b9dfdc8
> > 0000000300000001
> > [ 456.305069] ffff880097e21720 ffff88007b9dffd8 ffff88007b9dffd8
> > ffff88007b9dffd8
> > [ 456.305072] ffff880119b32e40 ffff880097e21720 ffff88007b9dfe28
> > ffff880118077800
> > [ 456.305076] Call Trace:
> > [ 456.305085] [<ffffffff816b7469>] schedule+0x29/0x70
> > [ 456.305089] [<ffffffff8129067d>] jbd2_log_wait_commit+0xcd/0x1a0
> > [ 456.305094] [<ffffffff8107eac0>] ? add_wait_queue+0x60/0x60
> > [ 456.305098] [<ffffffff812307a5>] ext4_sync_file+0x205/0x380
> > [ 456.305103] [<ffffffff811c43ad>] do_fsync+0x5d/0x90
> > [ 456.305108] [<ffffffff8119442b>] ? sys_write+0x6b/0xa0
> > [ 456.305111] [<ffffffff811c4790>] sys_fsync+0x10/0x20
> > [ 456.305114] [<ffffffff816c0edd>] system_call_fastpath+0x1a/0x1f
> > [ 456.305122]
> > [ 456.305124] Restarting tasks ... done.
> > [ 456.315056] video LNXVIDEO:00: Restoring backlight state
> >
> > After applying Eric's patch [5], I could not hit the call-trace again.
> > NOTE: The patch is from December 2012 and is not shipped in latest Linux-Next.
> >
> > The attached testcase script was helpful to force the call-trace.
> > I have run 50 loops of it w/o an issue!
> >
> > Feel free to add a Reported-by/Tested-by.
> > ( The issue kept me busy for the last days. )
> >
> > Regards,
> > - Sedat -
> >
> > [1] http://marc.info/?t=135283664600002&r=1&w=2
> > [2] http://marc.info/?t=135862023700004&r=1&w=2
> > [3] http://marc.info/?l=linux-kernel&m=135862010419101&w=2
> > [4] http://marc.info/?l=linux-next&m=135863550923093&w=2
> > [5] http://patchwork.ozlabs.org/patch/207237/
>
> Hi all,
>
> this is really ugly... I could cry!
>
> GRRR, I have hit the original issue again while running my testcase script!
>
> [ 363.831226] PM: Syncing filesystems ... done.
> [ 363.988855] PM: Preparing system for mem sleep
> [ 369.032965] Freezing user space processes ... (elapsed 0.11 seconds) done.
> [ 369.145792] Freezing remaining freezable tasks ...
> [ 389.137643] Freezing of tasks failed after 20.01 seconds (1 tasks
> refusing to freeze, wq_busy=0):
> [ 389.137760] jbd2/loop0-8 D ffffffff8180d780 0 295 2 0x00000000
> [ 389.137769] ffff8801181dfb68 0000000000000046 ffff880117de5c80
> 0000000000000001
> [ 389.137778] ffff880117de5c80 ffff8801181dffd8 ffff8801181dffd8
> ffff8801181dffd8
> [ 389.137784] ffffffff81c15440 ffff880117de5c80 ffff8801181dfb68
> ffff88011fa14738
> [ 389.137791] Call Trace:
> [ 389.137810] [<ffffffff811c6830>] ? __wait_on_buffer+0x30/0x30
> [ 389.137819] [<ffffffff816b7479>] schedule+0x29/0x70
> [ 389.137825] [<ffffffff816b754f>] io_schedule+0x8f/0xd0
> [ 389.137832] [<ffffffff811c683e>] sleep_on_buffer+0xe/0x20
> [ 389.137842] [<ffffffff816b5d4f>] __wait_on_bit+0x5f/0x90
> [ 389.137849] [<ffffffff811c5ef1>] ? submit_bh+0x121/0x1e0
> [ 389.137856] [<ffffffff811c6830>] ? __wait_on_buffer+0x30/0x30
> [ 389.137864] [<ffffffff816b5dfc>] out_of_line_wait_on_bit+0x7c/0x90
> [ 389.137873] [<ffffffff8107eb00>] ? autoremove_wake_function+0x40/0x40
> [ 389.137879] [<ffffffff811c682e>] __wait_on_buffer+0x2e/0x30
> [ 389.137891] [<ffffffff8128c02c>]
> jbd2_journal_commit_transaction+0x18cc/0x1d60
> [ 389.137899] [<ffffffff816b860e>] ? _raw_spin_lock_irqsave+0x2e/0x40
> [ 389.137908] [<ffffffff81069fbf>] ? try_to_del_timer_sync+0x4f/0x70
> [ 389.137915] [<ffffffff81290836>] kjournald2+0xd6/0x3e0
> [ 389.137921] [<ffffffff8107eac0>] ? add_wait_queue+0x60/0x60
> [ 389.137926] [<ffffffff81290760>] ? commit_timeout+0x10/0x10
> [ 389.137932] [<ffffffff8107ded0>] kthread+0xc0/0xd0
> [ 389.137939] [<ffffffff8107de10>] ? flush_kthread_worker+0xb0/0xb0
> [ 389.137946] [<ffffffff816c0e2c>] ret_from_fork+0x7c/0xb0
> [ 389.137951] [<ffffffff8107de10>] ? flush_kthread_worker+0xb0/0xb0
> [ 389.138017]
> [ 389.138021] Restarting kernel threads ... done.
> [ 389.138173] Restarting tasks ... done.
> [ 389.147980] video LNXVIDEO:00: Restoring backlight state
>
> I suspect there are still issues in JBD2 (BTW I run here EXT4FS).
>
> [ 389.137643] Freezing of tasks failed after 20.01 seconds (1 tasks
> refusing to freeze, wq_busy=0):
> [ 389.137760] jbd2/loop0-8 D ffffffff8180d780 0 295 2 0x00000000
>
> Have a good night, /me -> watching TV!
The traces don't suggest an ext4/jbd2 problem. What is happening is that
jbd2 is waiting for IO to finish and that never happens. Seeing that you
loop device I'd think it's some interaction of the loop device and
freezing. Can you reproduce the issue without the loop device (i.e. with
the filesystem directly on e.g. scsi disk)? I suspect the reason is
something like that the backing filesystem is already frozen so filesystem
on top of it cannot write all the data and hangs waiting for IO -> suspend
doesn't happen. Contents of /proc/mounts and losetup -l would help us
understand what's going on.
Honza
--
Jan Kara <jack@suse.cz>
SUSE Labs, CR
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-21 10:47 ` Jan Kara
@ 2013-01-21 11:40 ` Sedat Dilek
2013-01-21 12:30 ` Sedat Dilek
2013-01-21 12:02 ` Carlos Maiolino
1 sibling, 1 reply; 26+ messages in thread
From: Sedat Dilek @ 2013-01-21 11:40 UTC (permalink / raw)
To: Jan Kara
Cc: Eric Sandeen, linux-fsdevel, Ext4 Developers List,
Theodore Ts'o, LKML, linux-next
[-- Attachment #1: Type: text/plain, Size: 9852 bytes --]
On Mon, Jan 21, 2013 at 11:47 AM, Jan Kara <jack@suse.cz> wrote:
> On Sun 20-01-13 01:06:40, Sedat Dilek wrote:
>> On Sun, Jan 20, 2013 at 12:44 AM, Sedat Dilek <sedat.dilek@gmail.com> wrote:
>> > Hi,
>> >
>> > I and some others hit a similiar problem in Linux-Next
>> > (next-20130118), please see [1] and [2].
>> >
>> > [3] has a interim analyze of my problems.
>> >
>> > After suspecting the problem was caused by TTY-NEXT, it turned out to
>> > be a JBD2 problem finally.
>> > The freezer/pm_test was helpful to hit the issue (Thanks Rafael for the hint!).
>> >
>> > So, the issue has two faces: TTY and JBD2.
>> > [4] gives a list and URLs of the patches I had to apply to have a
>> > clean system again.
>> >
>> > After applying the two TTY patches (without Eric's JBD2-fix!) the
>> > call-trace after freezer/pm_test looked like this;
>> >
>> > [ 433.527986] PM: Syncing filesystems ... done.
>> > [ 433.843761] PM: Preparing system for mem sleep
>> > [ 436.306002] Freezing user space processes ...
>> > [ 456.304956] Freezing of tasks failed after 20.01 seconds (1 tasks
>> > refusing to freeze, wq_busy=0):
>> > [ 456.305060] Cache I/O D ffffffff8180d780 0 2132 1 0x00000004
>> > [ 456.305065] ffff88007b9dfe18 0000000000000046 ffff88007b9dfdc8
>> > 0000000300000001
>> > [ 456.305069] ffff880097e21720 ffff88007b9dffd8 ffff88007b9dffd8
>> > ffff88007b9dffd8
>> > [ 456.305072] ffff880119b32e40 ffff880097e21720 ffff88007b9dfe28
>> > ffff880118077800
>> > [ 456.305076] Call Trace:
>> > [ 456.305085] [<ffffffff816b7469>] schedule+0x29/0x70
>> > [ 456.305089] [<ffffffff8129067d>] jbd2_log_wait_commit+0xcd/0x1a0
>> > [ 456.305094] [<ffffffff8107eac0>] ? add_wait_queue+0x60/0x60
>> > [ 456.305098] [<ffffffff812307a5>] ext4_sync_file+0x205/0x380
>> > [ 456.305103] [<ffffffff811c43ad>] do_fsync+0x5d/0x90
>> > [ 456.305108] [<ffffffff8119442b>] ? sys_write+0x6b/0xa0
>> > [ 456.305111] [<ffffffff811c4790>] sys_fsync+0x10/0x20
>> > [ 456.305114] [<ffffffff816c0edd>] system_call_fastpath+0x1a/0x1f
>> > [ 456.305122]
>> > [ 456.305124] Restarting tasks ... done.
>> > [ 456.315056] video LNXVIDEO:00: Restoring backlight state
>> >
>> > After applying Eric's patch [5], I could not hit the call-trace again.
>> > NOTE: The patch is from December 2012 and is not shipped in latest Linux-Next.
>> >
>> > The attached testcase script was helpful to force the call-trace.
>> > I have run 50 loops of it w/o an issue!
>> >
>> > Feel free to add a Reported-by/Tested-by.
>> > ( The issue kept me busy for the last days. )
>> >
>> > Regards,
>> > - Sedat -
>> >
>> > [1] http://marc.info/?t=135283664600002&r=1&w=2
>> > [2] http://marc.info/?t=135862023700004&r=1&w=2
>> > [3] http://marc.info/?l=linux-kernel&m=135862010419101&w=2
>> > [4] http://marc.info/?l=linux-next&m=135863550923093&w=2
>> > [5] http://patchwork.ozlabs.org/patch/207237/
>>
>> Hi all,
>>
>> this is really ugly... I could cry!
>>
>> GRRR, I have hit the original issue again while running my testcase script!
>>
>> [ 363.831226] PM: Syncing filesystems ... done.
>> [ 363.988855] PM: Preparing system for mem sleep
>> [ 369.032965] Freezing user space processes ... (elapsed 0.11 seconds) done.
>> [ 369.145792] Freezing remaining freezable tasks ...
>> [ 389.137643] Freezing of tasks failed after 20.01 seconds (1 tasks
>> refusing to freeze, wq_busy=0):
>> [ 389.137760] jbd2/loop0-8 D ffffffff8180d780 0 295 2 0x00000000
>> [ 389.137769] ffff8801181dfb68 0000000000000046 ffff880117de5c80
>> 0000000000000001
>> [ 389.137778] ffff880117de5c80 ffff8801181dffd8 ffff8801181dffd8
>> ffff8801181dffd8
>> [ 389.137784] ffffffff81c15440 ffff880117de5c80 ffff8801181dfb68
>> ffff88011fa14738
>> [ 389.137791] Call Trace:
>> [ 389.137810] [<ffffffff811c6830>] ? __wait_on_buffer+0x30/0x30
>> [ 389.137819] [<ffffffff816b7479>] schedule+0x29/0x70
>> [ 389.137825] [<ffffffff816b754f>] io_schedule+0x8f/0xd0
>> [ 389.137832] [<ffffffff811c683e>] sleep_on_buffer+0xe/0x20
>> [ 389.137842] [<ffffffff816b5d4f>] __wait_on_bit+0x5f/0x90
>> [ 389.137849] [<ffffffff811c5ef1>] ? submit_bh+0x121/0x1e0
>> [ 389.137856] [<ffffffff811c6830>] ? __wait_on_buffer+0x30/0x30
>> [ 389.137864] [<ffffffff816b5dfc>] out_of_line_wait_on_bit+0x7c/0x90
>> [ 389.137873] [<ffffffff8107eb00>] ? autoremove_wake_function+0x40/0x40
>> [ 389.137879] [<ffffffff811c682e>] __wait_on_buffer+0x2e/0x30
>> [ 389.137891] [<ffffffff8128c02c>]
>> jbd2_journal_commit_transaction+0x18cc/0x1d60
>> [ 389.137899] [<ffffffff816b860e>] ? _raw_spin_lock_irqsave+0x2e/0x40
>> [ 389.137908] [<ffffffff81069fbf>] ? try_to_del_timer_sync+0x4f/0x70
>> [ 389.137915] [<ffffffff81290836>] kjournald2+0xd6/0x3e0
>> [ 389.137921] [<ffffffff8107eac0>] ? add_wait_queue+0x60/0x60
>> [ 389.137926] [<ffffffff81290760>] ? commit_timeout+0x10/0x10
>> [ 389.137932] [<ffffffff8107ded0>] kthread+0xc0/0xd0
>> [ 389.137939] [<ffffffff8107de10>] ? flush_kthread_worker+0xb0/0xb0
>> [ 389.137946] [<ffffffff816c0e2c>] ret_from_fork+0x7c/0xb0
>> [ 389.137951] [<ffffffff8107de10>] ? flush_kthread_worker+0xb0/0xb0
>> [ 389.138017]
>> [ 389.138021] Restarting kernel threads ... done.
>> [ 389.138173] Restarting tasks ... done.
>> [ 389.147980] video LNXVIDEO:00: Restoring backlight state
>>
>> I suspect there are still issues in JBD2 (BTW I run here EXT4FS).
>>
>> [ 389.137643] Freezing of tasks failed after 20.01 seconds (1 tasks
>> refusing to freeze, wq_busy=0):
>> [ 389.137760] jbd2/loop0-8 D ffffffff8180d780 0 295 2 0x00000000
>>
>> Have a good night, /me -> watching TV!
> The traces don't suggest an ext4/jbd2 problem. What is happening is that
> jbd2 is waiting for IO to finish and that never happens. Seeing that you
> loop device I'd think it's some interaction of the loop device and
> freezing. Can you reproduce the issue without the loop device (i.e. with
> the filesystem directly on e.g. scsi disk)? I suspect the reason is
> something like that the backing filesystem is already frozen so filesystem
> on top of it cannot write all the data and hangs waiting for IO -> suspend
> doesn't happen. Contents of /proc/mounts and losetup -l would help us
> understand what's going on.
>
As said I am here in a very uncommon WUBI environment means my
Ubuntu/precise rootfs-image lays on the Win7-partition (NTFS).
Your explanation sounds reasonable to me as this line from my attached
testcase causes the troubles.
echo mem > /sys/power/state && sleep 1
So, /sys/ is not writable immediately after freezer ends
I checked again and again my logs and have seen "starving" lines
reported by rtkit-daemon, but did not really get wiser what they want
to tell me. Stopping rtkit-daemon or resetting all or all-known
threads before running my pm_test/freezer did not help, too.
/usr/sbin/rtkitctl --help
rtkitctl [options]
-h, --help Show this help
--version Show version
--reset-known Reset real-time status of known threads
--reset-all Reset real-time status of all threads
--start Start RealtimeKit if it is not running already
-k, --exit Terminate running RealtimeKit daemon
Here are the outputs you wanted with some more (fstab, grub-config) etc.
I have here no -l option for losetup command.
- Sedat -
P.S.: Outputs for Honza...
$ sudo cat /proc/mounts
rootfs / rootfs rw 0 0
sysfs /sys sysfs rw,nosuid,nodev,noexec,relatime 0 0
proc /proc proc rw,nosuid,nodev,noexec,relatime 0 0
udev /dev devtmpfs rw,relatime,size=1966948k,nr_inodes=491737,mode=755 0 0
devpts /dev/pts devpts rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000 0 0
tmpfs /run tmpfs rw,nosuid,relatime,size=788076k,mode=755 0 0
/dev/sda2 /host fuseblk
rw,nosuid,nodev,relatime,user_id=0,group_id=0,allow_other,blksize=4096
0 0
/dev/loop0 / ext4 rw,relatime,errors=remount-ro,data=ordered 0 0
none /sys/fs/fuse/connections fusectl rw,relatime 0 0
none /sys/kernel/debug debugfs rw,relatime 0 0
none /sys/kernel/security securityfs rw,relatime 0 0
none /run/lock tmpfs rw,nosuid,nodev,noexec,relatime,size=5120k 0 0
none /run/shm tmpfs rw,nosuid,nodev,relatime 0 0
gvfs-fuse-daemon /home/wearefam/.gvfs fuse.gvfs-fuse-daemon
rw,nosuid,nodev,relatime,user_id=1000,group_id=1000 0 0
$ sudo losetup --all --verbose
/dev/loop0: [0802]:17982 (/host/ubuntu/disks/root.disk)
$ sudo losetup --find --verbose
Loop device is /dev/loop1
/dev/loop1
[ /etc/fstab ]
# /etc/fstab: static file system information.
# Use 'blkid' to print the universally unique identifier for a
# device; this may be used with UUID= as a more robust way to name devices
# that works even if disks are added and removed. See fstab(5).
# <file system> <mount point> <type> <options>
<dump> <pass>
proc /proc proc
nodev,noexec,nosuid 0 0
/host/ubuntu/disks/root.disk / ext4
loop,errors=remount-ro 0 1
/host/ubuntu/disks/swap.disk none swap loop,sw
0 0
- EOF -
[ /boot/grub/grub.cfg ]
...
menuentry 'Ubuntu, mit Linux 3.8.0-rc4-next20130121-1-iniza-generic'
--class ubuntu --class gnu-linux --class gnu --class os {
set gfxpayload=$linux_gfx_mode
insmod part_msdos
insmod ntfs
set root='(hd0,msdos2)'
search --no-floppy --fs-uuid --set=root 001AADA61AAD9964
loopback loop0 /ubuntu/disks/root.disk
set root=(loop0)
linux /boot/vmlinuz-3.8.0-rc4-next20130121-1-iniza-generic
root=UUID=001AADA61AAD9964 loop=/ubuntu/disks/root.disk ro
initrd /boot/initrd.img-3.8.0-rc4-next20130121-1-iniza-generic
}
...
Hope this helps you!
Regards,
- Sedat -
> Honza
> --
> Jan Kara <jack@suse.cz>
> SUSE Labs, CR
[-- Attachment #2: syslog.txt --]
[-- Type: text/plain, Size: 58447 bytes --]
Jan 21 08:11:23 fambox NetworkManager[1132]: <info> sleep requested (sleeping: no enabled: yes)
Jan 21 08:11:23 fambox NetworkManager[1132]: <info> sleeping or disabling...
Jan 21 08:11:23 fambox NetworkManager[1132]: <info> (wlan0): now unmanaged
Jan 21 08:11:23 fambox NetworkManager[1132]: <info> (wlan0): device state change: activated -> unmanaged (reason 'sleeping') [100 10 37]
Jan 21 08:11:23 fambox NetworkManager[1132]: <info> (wlan0): deactivating device (reason 'sleeping') [37]
Jan 21 08:11:23 fambox NetworkManager[1132]: <info> (wlan0): canceled DHCP transaction, DHCP client pid 1516
Jan 21 08:11:23 fambox kernel: [ 244.792739] wlan0: deauthenticating from 00:04:0e:e4:00:3d by local choice (reason=3)
Jan 21 08:11:23 fambox avahi-daemon[1031]: Withdrawing address record for 192.168.178.22 on wlan0.
Jan 21 08:11:23 fambox avahi-daemon[1031]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.178.22.
Jan 21 08:11:23 fambox dnsmasq[1760]: exiting on receipt of SIGTERM
Jan 21 08:11:23 fambox avahi-daemon[1031]: Interface wlan0.IPv4 no longer relevant for mDNS.
Jan 21 08:11:23 fambox avahi-daemon[1031]: Withdrawing address record for 2001:4dd0:f889:0:419:23bf:c9c3:c4da on wlan0.
Jan 21 08:11:23 fambox avahi-daemon[1031]: Leaving mDNS multicast group on interface wlan0.IPv6 with address 2001:4dd0:f889:0:419:23bf:c9c3:c4da.
Jan 21 08:11:23 fambox avahi-daemon[1031]: Joining mDNS multicast group on interface wlan0.IPv6 with address 2001:4dd0:f889:0:8a53:2eff:feac:c312.
Jan 21 08:11:23 fambox kernel: [ 244.806345] cfg80211: Calling CRDA to update world regulatory domain
Jan 21 08:11:23 fambox avahi-daemon[1031]: Withdrawing address record for 2001:4dd0:f889:0:8a53:2eff:feac:c312 on wlan0.
Jan 21 08:11:23 fambox avahi-daemon[1031]: Leaving mDNS multicast group on interface wlan0.IPv6 with address 2001:4dd0:f889:0:8a53:2eff:feac:c312.
Jan 21 08:11:23 fambox avahi-daemon[1031]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::8a53:2eff:feac:c312.
Jan 21 08:11:23 fambox avahi-daemon[1031]: Registering new address record for fe80::8a53:2eff:feac:c312 on wlan0.*.
Jan 21 08:11:23 fambox NetworkManager[1132]: <info> DNS: starting dnsmasq...
Jan 21 08:11:23 fambox NetworkManager[1132]: <info> (wlan0): writing resolv.conf to /sbin/resolvconf
Jan 21 08:11:23 fambox wpa_supplicant[1394]: wlan0: CTRL-EVENT-DISCONNECTED bssid=00:00:00:00:00:00 reason=3
Jan 21 08:11:24 fambox kernel: [ 244.816996] cfg80211: World regulatory domain updated:
Jan 21 08:11:24 fambox kernel: [ 244.817007] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
Jan 21 08:11:24 fambox kernel: [ 244.817013] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Jan 21 08:11:24 fambox kernel: [ 244.817018] cfg80211: (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
Jan 21 08:11:24 fambox kernel: [ 244.817021] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
Jan 21 08:11:24 fambox kernel: [ 244.817025] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Jan 21 08:11:24 fambox kernel: [ 244.817028] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Jan 21 08:11:24 fambox dnsmasq[2380]: started, version 2.59 cache disabled
Jan 21 08:11:24 fambox dnsmasq[2380]: compile time options: IPv6 GNU-getopt DBus i18n DHCP TFTP conntrack IDN
Jan 21 08:11:24 fambox dnsmasq[2380]: warning: no upstream servers configured
Jan 21 08:11:24 fambox dnsmasq[2380]: exiting on receipt of SIGTERM
Jan 21 08:11:24 fambox NetworkManager[1132]: <info> DNS: starting dnsmasq...
Jan 21 08:11:24 fambox NetworkManager[1132]: <info> (wlan0): writing resolv.conf to /sbin/resolvconf
Jan 21 08:11:24 fambox dnsmasq[2416]: started, version 2.59 cache disabled
Jan 21 08:11:24 fambox dnsmasq[2416]: compile time options: IPv6 GNU-getopt DBus i18n DHCP TFTP conntrack IDN
Jan 21 08:11:24 fambox dnsmasq[2416]: warning: no upstream servers configured
Jan 21 08:11:24 fambox NetworkManager[1132]: <info> (wlan0): cleaning up...
Jan 21 08:11:24 fambox NetworkManager[1132]: <info> (wlan0): taking down device.
Jan 21 08:11:24 fambox avahi-daemon[1031]: Interface wlan0.IPv6 no longer relevant for mDNS.
Jan 21 08:11:24 fambox avahi-daemon[1031]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::8a53:2eff:feac:c312.
Jan 21 08:11:24 fambox avahi-daemon[1031]: Withdrawing address record for fe80::8a53:2eff:feac:c312 on wlan0.
Jan 21 08:11:24 fambox dbus[865]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Jan 21 08:11:24 fambox dbus[865]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Jan 21 08:11:25 fambox kernel: [ 246.688282] PM: Syncing filesystems ... done.
Jan 21 08:11:25 fambox kernel: [ 246.693207] PM: Preparing system for mem sleep
Jan 21 08:11:38 fambox kernel: [ 248.377923] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:11:38 fambox kernel: [ 248.393228] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:11:38 fambox kernel: [ 248.409192] PM: Entering mem sleep
Jan 21 08:11:38 fambox kernel: [ 248.409256] Suspending console(s) (use no_console_suspend to debug)
Jan 21 08:11:38 fambox kernel: [ 248.409485] sd 1:0:0:0: [sdb] Synchronizing SCSI cache
Jan 21 08:11:38 fambox kernel: [ 248.409534] sd 0:0:0:0: [sda] Synchronizing SCSI cache
Jan 21 08:11:38 fambox kernel: [ 248.409692] sd 0:0:0:0: [sda] Stopping disk
Jan 21 08:11:38 fambox kernel: [ 248.412157] sd 1:0:0:0: [sdb] Stopping disk
Jan 21 08:11:38 fambox kernel: [ 249.028442] PM: suspend of devices complete after 619.821 msecs
Jan 21 08:11:38 fambox kernel: [ 249.028587] PM: late suspend of devices complete after 0.143 msecs
Jan 21 08:11:38 fambox kernel: [ 249.044387] r8169 0000:02:00.0: System wakeup enabled by ACPI
Jan 21 08:11:38 fambox kernel: [ 249.124225] PM: noirq suspend of devices complete after 95.750 msecs
Jan 21 08:11:38 fambox kernel: [ 249.124491] ACPI: Preparing to enter system sleep state S3
Jan 21 08:11:38 fambox kernel: [ 249.148265] PM: Saving platform NVS memory
Jan 21 08:11:38 fambox kernel: [ 249.153095] Disabling non-boot CPUs ...
Jan 21 08:11:38 fambox kernel: [ 249.256055] smpboot: CPU 1 is now offline
Jan 21 08:11:38 fambox kernel: [ 249.359925] smpboot: CPU 2 is now offline
Jan 21 08:11:38 fambox kernel: [ 249.360418] Broke affinity for irq 23
Jan 21 08:11:38 fambox kernel: [ 249.463784] smpboot: CPU 3 is now offline
Jan 21 08:11:38 fambox kernel: [ 249.464123] Extended CMOS year: 2000
Jan 21 08:11:38 fambox kernel: [ 249.465361] ACPI: Low-level resume complete
Jan 21 08:11:38 fambox kernel: [ 249.465404] PM: Restoring platform NVS memory
Jan 21 08:11:38 fambox kernel: [ 249.466621] Extended CMOS year: 2000
Jan 21 08:11:38 fambox kernel: [ 249.466693] Enabling non-boot CPUs ...
Jan 21 08:11:38 fambox kernel: [ 249.466771] smpboot: Booting Node 0 Processor 1 APIC 0x1
Jan 21 08:11:38 fambox kernel: [ 249.477873] Disabled fast string operations
Jan 21 08:11:38 fambox kernel: [ 249.480182] CPU1 is up
Jan 21 08:11:38 fambox kernel: [ 249.480252] smpboot: Booting Node 0 Processor 2 APIC 0x2
Jan 21 08:11:38 fambox kernel: [ 249.491287] Disabled fast string operations
Jan 21 08:11:38 fambox kernel: [ 249.493605] CPU2 is up
Jan 21 08:11:38 fambox kernel: [ 249.493676] smpboot: Booting Node 0 Processor 3 APIC 0x3
Jan 21 08:11:38 fambox kernel: [ 249.504712] Disabled fast string operations
Jan 21 08:11:38 fambox kernel: [ 249.507110] CPU3 is up
Jan 21 08:11:38 fambox kernel: [ 249.511892] ACPI: Waking up from system sleep state S3
Jan 21 08:11:38 fambox kernel: [ 249.706123] PM: noirq resume of devices complete after 144.003 msecs
Jan 21 08:11:38 fambox kernel: [ 249.706274] PM: early resume of devices complete after 0.111 msecs
Jan 21 08:11:38 fambox kernel: [ 249.706310] i915 0000:00:02.0: setting latency timer to 64
Jan 21 08:11:38 fambox kernel: [ 249.706333] ehci-pci 0000:00:1a.0: setting latency timer to 64
Jan 21 08:11:38 fambox kernel: [ 249.706387] mei 0000:00:16.0: irq 47 for MSI/MSI-X
Jan 21 08:11:38 fambox kernel: [ 249.706429] ehci-pci 0000:00:1d.0: setting latency timer to 64
Jan 21 08:11:38 fambox kernel: [ 249.706447] snd_hda_intel 0000:00:1b.0: irq 50 for MSI/MSI-X
Jan 21 08:11:38 fambox kernel: [ 249.706508] r8169 0000:02:00.0: System wakeup disabled by ACPI
Jan 21 08:11:38 fambox kernel: [ 249.706622] usb usb3: root hub lost power or was reset
Jan 21 08:11:38 fambox kernel: [ 249.706624] usb usb4: root hub lost power or was reset
Jan 21 08:11:38 fambox kernel: [ 249.706626] iwlwifi 0000:01:00.0: RF_KILL bit toggled to enable radio.
Jan 21 08:11:38 fambox kernel: [ 249.706686] ahci 0000:00:1f.2: setting latency timer to 64
Jan 21 08:11:38 fambox kernel: [ 249.711344] xhci_hcd 0000:03:00.0: irq 41 for MSI/MSI-X
Jan 21 08:11:38 fambox kernel: [ 249.711352] xhci_hcd 0000:03:00.0: irq 42 for MSI/MSI-X
Jan 21 08:11:38 fambox kernel: [ 249.711360] xhci_hcd 0000:03:00.0: irq 43 for MSI/MSI-X
Jan 21 08:11:38 fambox kernel: [ 249.711369] xhci_hcd 0000:03:00.0: irq 44 for MSI/MSI-X
Jan 21 08:11:38 fambox kernel: [ 249.711376] xhci_hcd 0000:03:00.0: irq 45 for MSI/MSI-X
Jan 21 08:11:38 fambox kernel: [ 250.041632] ata2: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jan 21 08:11:38 fambox kernel: [ 250.045709] ata2.00: configured for UDMA/133
Jan 21 08:11:38 fambox kernel: [ 250.049618] ata4: SATA link down (SStatus 0 SControl 300)
Jan 21 08:11:38 fambox kernel: [ 250.057610] ata5: SATA link down (SStatus 0 SControl 300)
Jan 21 08:11:38 fambox kernel: [ 250.061687] sd 1:0:0:0: [sdb] Starting disk
Jan 21 08:11:38 fambox kernel: [ 250.117763] usb 1-1.2: reset low-speed USB device number 3 using ehci-pci
Jan 21 08:11:38 fambox kernel: [ 250.469164] usb 1-1.4: reset high-speed USB device number 4 using ehci-pci
Jan 21 08:11:38 fambox kernel: [ 251.528028] [drm] Enabling RC6 states: RC6 on, RC6p off, RC6pp off
Jan 21 08:11:38 fambox kernel: [ 252.079185] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jan 21 08:11:38 fambox kernel: [ 252.081625] ata1.00: configured for UDMA/133
Jan 21 08:11:38 fambox kernel: [ 252.095265] sd 0:0:0:0: [sda] Starting disk
Jan 21 08:11:38 fambox kernel: [ 252.097227] Extended CMOS year: 2000
Jan 21 08:11:38 fambox kernel: [ 252.119773] PM: resume of devices complete after 2416.409 msecs
Jan 21 08:11:38 fambox kernel: [ 252.120213] PM: Finishing wakeup.
Jan 21 08:11:38 fambox kernel: [ 252.120216] Restarting tasks ... done.
Jan 21 08:11:38 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:11:38 fambox acpid: client connected from 1254[0:0]
Jan 21 08:11:38 fambox acpid: 1 client rule loaded
Jan 21 08:11:38 fambox kernel: [ 252.128944] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:11:38 fambox NetworkManager[1132]: <info> wake requested (sleeping: yes enabled: yes)
Jan 21 08:11:38 fambox NetworkManager[1132]: <info> waking up and re-enabling...
Jan 21 08:11:38 fambox NetworkManager[1132]: <info> WWAN now enabled by management service
Jan 21 08:11:38 fambox NetworkManager[1132]: <info> (wlan0): now managed
Jan 21 08:11:38 fambox NetworkManager[1132]: <info> (wlan0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Jan 21 08:11:38 fambox NetworkManager[1132]: <info> (wlan0): bringing up device.
Jan 21 08:11:38 fambox kernel: [ 252.719180] iwlwifi 0000:01:00.0: L1 Enabled; Disabling L0S
Jan 21 08:11:38 fambox kernel: [ 252.726034] iwlwifi 0000:01:00.0: Radio type=0x1-0x2-0x0
Jan 21 08:11:39 fambox NetworkManager[1132]: <info> (wlan0): preparing device.
Jan 21 08:11:39 fambox NetworkManager[1132]: <info> (wlan0): deactivating device (reason 'managed') [2]
Jan 21 08:11:39 fambox NetworkManager[1132]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
Jan 21 08:11:39 NetworkManager[1132]: last message repeated 2 times
Jan 21 08:11:39 fambox kernel: [ 252.955108] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Jan 21 08:11:39 fambox NetworkManager[1132]: <info> (wlan0): supplicant interface state: starting -> ready
Jan 21 08:11:39 fambox NetworkManager[1132]: <info> (wlan0): device state change: unavailable -> disconnected (reason 'supplicant-available') [20 30 42]
Jan 21 08:11:39 fambox NetworkManager[1132]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
Jan 21 08:11:39 fambox NetworkManager[1132]: <info> (wlan0): supplicant interface state: ready -> inactive
Jan 21 08:11:39 fambox NetworkManager[1132]: <warn> Trying to remove a non-existant call id.
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Auto-activating connection 'myCastle-WLAN WPA (Wireless LAN)'.
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Activation (wlan0) starting connection 'myCastle-WLAN WPA (Wireless LAN)'
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> (wlan0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Activation (wlan0/wireless): access point 'myCastle-WLAN WPA (Wireless LAN)' has security, but secrets are required.
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> (wlan0): device state change: config -> need-auth (reason 'none') [50 60 0]
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> (wlan0): device state change: need-auth -> prepare (reason 'none') [60 40 0]
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Activation (wlan0/wireless): connection 'myCastle-WLAN WPA (Wireless LAN)' has security, and secrets exist. No new secrets needed.
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Config: added 'ssid' value 'myCastle-WLAN WPA (Wireless LAN)'
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Config: added 'scan_ssid' value '1'
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Config: added 'key_mgmt' value 'WPA-PSK'
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Config: added 'psk' value '<omitted>'
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> Config: set interface ap_scan to 1
Jan 21 08:11:42 fambox NetworkManager[1132]: <info> (wlan0): supplicant interface state: inactive -> scanning
Jan 21 08:11:45 fambox wpa_supplicant[1394]: wlan0: SME: Trying to authenticate with 00:04:0e:e4:00:3d (SSID='myCastle-WLAN WPA (Wireless LAN)' freq=2442 MHz)
Jan 21 08:11:45 fambox kernel: [ 259.272806] wlan0: authenticate with 00:04:0e:e4:00:3d
Jan 21 08:11:45 fambox kernel: [ 259.281463] wlan0: send auth to 00:04:0e:e4:00:3d (try 1/3)
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> (wlan0): supplicant interface state: scanning -> authenticating
Jan 21 08:11:45 fambox wpa_supplicant[1394]: wlan0: Trying to associate with 00:04:0e:e4:00:3d (SSID='myCastle-WLAN WPA (Wireless LAN)' freq=2442 MHz)
Jan 21 08:11:45 fambox kernel: [ 259.283236] wlan0: authenticated
Jan 21 08:11:45 fambox kernel: [ 259.283530] iwlwifi 0000:01:00.0 wlan0: disabling HT as WMM/QoS is not supported by the AP
Jan 21 08:11:45 fambox kernel: [ 259.283541] iwlwifi 0000:01:00.0 wlan0: disabling VHT as WMM/QoS is not supported by the AP
Jan 21 08:11:45 fambox kernel: [ 259.286367] wlan0: associate with 00:04:0e:e4:00:3d (try 1/3)
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> (wlan0): supplicant interface state: authenticating -> associating
Jan 21 08:11:45 fambox kernel: [ 259.290482] wlan0: RX AssocResp from 00:04:0e:e4:00:3d (capab=0x411 status=0 aid=1)
Jan 21 08:11:45 fambox kernel: [ 259.294170] wlan0: associated
Jan 21 08:11:45 fambox kernel: [ 259.294205] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Jan 21 08:11:45 fambox wpa_supplicant[1394]: wlan0: Associated with 00:04:0e:e4:00:3d
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> (wlan0): supplicant interface state: associating -> 4-way handshake
Jan 21 08:11:45 fambox wpa_supplicant[1394]: wlan0: WPA: Key negotiation completed with 00:04:0e:e4:00:3d [PTK=CCMP GTK=TKIP]
Jan 21 08:11:45 fambox wpa_supplicant[1394]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:04:0e:e4:00:3d completed (auth) [id=0 id_str=]
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> (wlan0): supplicant interface state: 4-way handshake -> completed
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'myCastle-WLAN WPA (Wireless LAN)'.
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> (wlan0): device state change: config -> ip-config (reason 'none') [50 70 0]
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889)
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> Activation (wlan0) Beginning DHCPv4 transaction (timeout in 45 seconds)
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> dhclient started with pid 3137
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> Activation (wlan0) Beginning IP6 addrconf.
Jan 21 08:11:45 fambox dhclient: Internet Systems Consortium DHCP Client 4.1-ESV-R4
Jan 21 08:11:45 fambox dhclient: Copyright 2004-2011 Internet Systems Consortium.
Jan 21 08:11:45 fambox dhclient: All rights reserved.
Jan 21 08:11:45 fambox dhclient: For info, please visit https://www.isc.org/software/dhcp/
Jan 21 08:11:45 fambox dhclient:
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> (wlan0): DHCPv4 state changed nbi -> preinit
Jan 21 08:11:45 fambox dhclient: Listening on LPF/wlan0/88:53:2e:ac:c3:12
Jan 21 08:11:45 fambox dhclient: Sending on LPF/wlan0/88:53:2e:ac:c3:12
Jan 21 08:11:45 fambox dhclient: Sending on Socket/fallback
Jan 21 08:11:45 fambox dhclient: DHCPREQUEST of 192.168.178.22 on wlan0 to 255.255.255.255 port 67
Jan 21 08:11:45 fambox dhclient: DHCPACK of 192.168.178.22 from 192.168.178.1
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> (wlan0): DHCPv4 state changed preinit -> reboot
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> address 192.168.178.22
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> prefix 24 (255.255.255.0)
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> gateway 192.168.178.1
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> nameserver '192.168.178.1'
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> domain name 'fritz.box'
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Configure Commit) scheduled...
Jan 21 08:11:45 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Commit) started...
Jan 21 08:11:45 fambox avahi-daemon[1031]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.178.22.
Jan 21 08:11:45 fambox dhclient: bound to 192.168.178.22 -- renewal in 384734 seconds.
Jan 21 08:11:45 fambox avahi-daemon[1031]: New relevant interface wlan0.IPv4 for mDNS.
Jan 21 08:11:45 fambox avahi-daemon[1031]: Registering new address record for 192.168.178.22 on wlan0.IPv4.
Jan 21 08:11:46 fambox dnsmasq[2416]: exiting on receipt of SIGTERM
Jan 21 08:11:46 fambox NetworkManager[1132]: <info> DNS: starting dnsmasq...
Jan 21 08:11:46 fambox NetworkManager[1132]: <info> (wlan0): writing resolv.conf to /sbin/resolvconf
Jan 21 08:11:46 fambox dnsmasq[3140]: started, version 2.59 cache disabled
Jan 21 08:11:46 fambox dnsmasq[3140]: compile time options: IPv6 GNU-getopt DBus i18n DHCP TFTP conntrack IDN
Jan 21 08:11:46 fambox dnsmasq[3140]: using nameserver 192.168.178.1#53
Jan 21 08:11:46 fambox avahi-daemon[1031]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::8a53:2eff:feac:c312.
Jan 21 08:11:46 fambox avahi-daemon[1031]: New relevant interface wlan0.IPv6 for mDNS.
Jan 21 08:11:46 fambox avahi-daemon[1031]: Registering new address record for fe80::8a53:2eff:feac:c312 on wlan0.*.
Jan 21 08:11:46 fambox NetworkManager[1132]: <info> (wlan0): device state change: ip-config -> activated (reason 'none') [70 100 0]
Jan 21 08:11:46 fambox NetworkManager[1132]: <info> Policy set 'myCastle-WLAN WPA (Wireless LAN)' (wlan0) as default for IPv4 routing and DNS.
Jan 21 08:11:46 fambox NetworkManager[1132]: <info> Activation (wlan0) successful, device activated.
Jan 21 08:11:46 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Commit) complete.
Jan 21 08:11:46 fambox dbus[865]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Jan 21 08:11:46 fambox dbus[865]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Jan 21 08:11:47 fambox avahi-daemon[1031]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::8a53:2eff:feac:c312.
Jan 21 08:11:47 fambox avahi-daemon[1031]: Joining mDNS multicast group on interface wlan0.IPv6 with address 2001:4dd0:f889:0:419:23bf:c9c3:c4da.
Jan 21 08:11:47 fambox avahi-daemon[1031]: Registering new address record for 2001:4dd0:f889:0:419:23bf:c9c3:c4da on wlan0.*.
Jan 21 08:11:47 fambox avahi-daemon[1031]: Withdrawing address record for fe80::8a53:2eff:feac:c312 on wlan0.
Jan 21 08:11:47 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 5 of 5 (IPv6 Commit) scheduled...
Jan 21 08:11:47 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 5 of 5 (IPv6 Commit) started...
Jan 21 08:11:48 fambox avahi-daemon[1031]: Registering new address record for 2001:4dd0:f889:0:8a53:2eff:feac:c312 on wlan0.*.
Jan 21 08:11:48 fambox dnsmasq[3140]: exiting on receipt of SIGTERM
Jan 21 08:11:48 fambox NetworkManager[1132]: <info> DNS: starting dnsmasq...
Jan 21 08:11:48 fambox NetworkManager[1132]: <info> (wlan0): writing resolv.conf to /sbin/resolvconf
Jan 21 08:11:48 fambox dnsmasq[3216]: started, version 2.59 cache disabled
Jan 21 08:11:48 fambox dnsmasq[3216]: compile time options: IPv6 GNU-getopt DBus i18n DHCP TFTP conntrack IDN
Jan 21 08:11:48 fambox dnsmasq[3216]: using nameserver 192.168.178.1#53
Jan 21 08:11:48 fambox NetworkManager[1132]: <info> Policy set 'myCastle-WLAN WPA (Wireless LAN)' (wlan0) as default for IPv4 routing and DNS.
Jan 21 08:11:48 fambox NetworkManager[1132]: <info> Policy set 'myCastle-WLAN WPA (Wireless LAN)' (wlan0) as default for IPv6 routing and DNS.
Jan 21 08:11:48 fambox NetworkManager[1132]: <info> Activation (wlan0) Stage 5 of 5 (IPv6 Commit) complete.
Jan 21 08:11:55 fambox ntpdate[3201]: adjust time server 91.189.94.4 offset -0.148119 sec
Jan 21 08:12:33 fambox kernel: [ 307.235839] show_signal_msg: 36 callbacks suppressed
Jan 21 08:12:33 fambox kernel: [ 307.235844] firefox[3244]: segfault at 7fd133927428 ip 00007fd133908362 sp 00007fff8cfda778 error 7 in libGL.so.1.2.0[7fd133908000+7c000]
Jan 21 08:13:28 fambox kernel: [ 362.220464] PM: Syncing filesystems ... done.
Jan 21 08:13:28 fambox kernel: [ 362.385356] PM: Preparing system for mem sleep
Jan 21 08:13:37 fambox kernel: [ 366.625489] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:13:37 fambox kernel: [ 366.641644] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:13:37 fambox kernel: [ 366.657666] suspend debug: Waiting for 5 seconds.
Jan 21 08:13:37 fambox kernel: [ 371.614417] PM: Finishing wakeup.
Jan 21 08:13:37 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:13:37 fambox kernel: [ 371.614419] Restarting tasks ... done.
Jan 21 08:13:37 fambox kernel: [ 371.624384] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:13:37 fambox acpid: client connected from 1254[0:0]
Jan 21 08:13:37 fambox acpid: 1 client rule loaded
Jan 21 08:13:39 fambox kernel: [ 372.627309] PM: Syncing filesystems ... done.
Jan 21 08:13:39 fambox kernel: [ 372.769925] PM: Preparing system for mem sleep
Jan 21 08:13:46 fambox kernel: [ 375.343360] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:13:46 fambox kernel: [ 375.359732] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:13:46 fambox kernel: [ 375.375833] suspend debug: Waiting for 5 seconds.
Jan 21 08:13:46 fambox kernel: [ 380.332539] PM: Finishing wakeup.
Jan 21 08:13:46 fambox kernel: [ 380.332540] Restarting tasks ... done.
Jan 21 08:13:46 fambox kernel: [ 380.345274] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:13:46 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:13:46 fambox acpid: client connected from 1254[0:0]
Jan 21 08:13:46 fambox acpid: 1 client rule loaded
Jan 21 08:13:47 fambox kernel: [ 381.347598] PM: Syncing filesystems ... done.
Jan 21 08:13:47 fambox kernel: [ 381.612879] PM: Preparing system for mem sleep
Jan 21 08:13:56 fambox kernel: [ 384.777396] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:13:56 fambox kernel: [ 384.793742] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:13:56 fambox kernel: [ 384.809867] suspend debug: Waiting for 5 seconds.
Jan 21 08:13:56 fambox kernel: [ 389.766559] PM: Finishing wakeup.
Jan 21 08:13:56 fambox kernel: [ 389.766562] Restarting tasks ... done.
Jan 21 08:13:56 fambox kernel: [ 389.772358] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:13:56 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:13:56 fambox acpid: client connected from 1254[0:0]
Jan 21 08:13:56 fambox acpid: 1 client rule loaded
Jan 21 08:13:57 fambox kernel: [ 390.775105] PM: Syncing filesystems ... done.
Jan 21 08:13:57 fambox kernel: [ 391.052390] PM: Preparing system for mem sleep
Jan 21 08:14:04 fambox kernel: [ 393.723525] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:14:04 fambox kernel: [ 393.740009] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:14:04 fambox kernel: [ 393.756006] suspend debug: Waiting for 5 seconds.
Jan 21 08:14:04 fambox kernel: [ 398.712691] PM: Finishing wakeup.
Jan 21 08:14:04 fambox kernel: [ 398.712693] Restarting tasks ... done.
Jan 21 08:14:04 fambox kernel: [ 398.720021] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:14:04 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:14:04 fambox acpid: client connected from 1254[0:0]
Jan 21 08:14:04 fambox acpid: 1 client rule loaded
Jan 21 08:14:06 fambox kernel: [ 399.721844] PM: Syncing filesystems ... done.
Jan 21 08:14:06 fambox kernel: [ 400.115853] PM: Preparing system for mem sleep
Jan 21 08:14:12 fambox kernel: [ 401.760938] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:14:12 fambox kernel: [ 401.774315] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:14:12 fambox kernel: [ 401.790297] suspend debug: Waiting for 5 seconds.
Jan 21 08:14:12 fambox kernel: [ 406.746991] PM: Finishing wakeup.
Jan 21 08:14:12 fambox kernel: [ 406.746993] Restarting tasks ... done.
Jan 21 08:14:13 fambox kernel: [ 406.758469] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:14:13 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:14:13 fambox acpid: client connected from 1254[0:0]
Jan 21 08:14:13 fambox acpid: 1 client rule loaded
Jan 21 08:14:14 fambox kernel: [ 407.763922] PM: Syncing filesystems ... done.
Jan 21 08:14:14 fambox kernel: [ 407.867994] PM: Preparing system for mem sleep
Jan 21 08:14:22 fambox kernel: [ 410.811958] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:14:22 fambox kernel: [ 410.828400] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:14:22 fambox kernel: [ 410.844408] suspend debug: Waiting for 5 seconds.
Jan 21 08:14:22 fambox kernel: [ 415.801093] PM: Finishing wakeup.
Jan 21 08:14:22 fambox AptDaemon: INFO: Quitting due to inactivity
Jan 21 08:14:22 fambox AptDaemon: INFO: Quitting was requested
Jan 21 08:14:22 fambox kernel: [ 415.801095] Restarting tasks ... done.
Jan 21 08:14:22 fambox kernel: [ 415.808417] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:14:22 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:14:22 fambox acpid: client connected from 1254[0:0]
Jan 21 08:14:22 fambox acpid: 1 client rule loaded
Jan 21 08:14:23 fambox kernel: [ 416.811223] PM: Syncing filesystems ... done.
Jan 21 08:14:23 fambox kernel: [ 416.909207] PM: Preparing system for mem sleep
Jan 21 08:14:30 fambox kernel: [ 418.902297] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:14:30 fambox kernel: [ 418.918607] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:14:30 fambox kernel: [ 418.934718] suspend debug: Waiting for 5 seconds.
Jan 21 08:14:30 fambox kernel: [ 423.891419] PM: Finishing wakeup.
Jan 21 08:14:30 fambox kernel: [ 423.891421] Restarting tasks ... done.
Jan 21 08:14:30 fambox kernel: [ 423.897050] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:14:30 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:14:30 fambox acpid: client connected from 1254[0:0]
Jan 21 08:14:30 fambox acpid: 1 client rule loaded
Jan 21 08:14:31 fambox kernel: [ 424.902824] PM: Syncing filesystems ... done.
Jan 21 08:14:31 fambox kernel: [ 425.005597] PM: Preparing system for mem sleep
Jan 21 08:14:39 fambox kernel: [ 427.936413] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:14:39 fambox kernel: [ 427.952668] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:14:39 fambox kernel: [ 427.968820] suspend debug: Waiting for 5 seconds.
Jan 21 08:14:39 fambox kernel: [ 432.925545] PM: Finishing wakeup.
Jan 21 08:14:39 fambox kernel: [ 432.925547] Restarting tasks ... done.
Jan 21 08:14:39 fambox kernel: [ 432.933531] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:14:39 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:14:39 fambox acpid: client connected from 1254[0:0]
Jan 21 08:14:39 fambox acpid: 1 client rule loaded
Jan 21 08:14:40 fambox kernel: [ 433.936467] PM: Syncing filesystems ... done.
Jan 21 08:14:40 fambox kernel: [ 434.309510] PM: Preparing system for mem sleep
Jan 21 08:14:48 fambox kernel: [ 436.806416] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:14:48 fambox kernel: [ 436.822973] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:14:48 fambox kernel: [ 436.838930] suspend debug: Waiting for 5 seconds.
Jan 21 08:14:48 fambox kernel: [ 441.795587] PM: Finishing wakeup.
Jan 21 08:14:48 fambox kernel: [ 441.795589] Restarting tasks ... done.
Jan 21 08:14:48 fambox kernel: [ 441.801976] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:14:48 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:14:48 fambox acpid: client connected from 1254[0:0]
Jan 21 08:14:48 fambox acpid: 1 client rule loaded
Jan 21 08:14:49 fambox kernel: [ 442.804254] PM: Syncing filesystems ... done.
Jan 21 08:14:49 fambox kernel: [ 443.050353] PM: Preparing system for mem sleep
Jan 21 08:14:58 fambox kernel: [ 446.936427] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:14:58 fambox kernel: [ 446.952810] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:14:58 fambox kernel: [ 446.968839] suspend debug: Waiting for 5 seconds.
Jan 21 08:14:58 fambox kernel: [ 451.925556] PM: Finishing wakeup.
Jan 21 08:14:58 fambox rtkit-daemon[1808]: The canary thread is apparently starving. Taking action.
Jan 21 08:14:58 fambox rtkit-daemon[1808]: Demoting known real-time threads.
Jan 21 08:14:58 fambox rtkit-daemon[1808]: Successfully demoted thread 1972 of process 1968 (n/a).
Jan 21 08:14:58 fambox rtkit-daemon[1808]: Successfully demoted thread 1969 of process 1968 (n/a).
Jan 21 08:14:58 fambox rtkit-daemon[1808]: Successfully demoted thread 1968 of process 1968 (n/a).
Jan 21 08:14:58 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:14:58 fambox rtkit-daemon[1808]: Demoted 3 threads.
Jan 21 08:14:58 fambox kernel: [ 451.925558] Restarting tasks ... done.
Jan 21 08:14:58 fambox kernel: [ 451.930859] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:14:58 fambox acpid: client connected from 1254[0:0]
Jan 21 08:14:58 fambox acpid: 1 client rule loaded
Jan 21 08:17:01 fambox CRON[3403]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Jan 21 08:17:37 fambox kernel: [ 611.195107] SGI XFS with ACLs, security attributes, realtime, large block/inode numbers, no debug enabled
Jan 21 08:17:37 fambox kernel: [ 611.276930] Btrfs loaded
Jan 21 08:17:37 fambox os-prober: debug: running /usr/lib/os-probes/50mounted-tests on /dev/sda1
Jan 21 08:17:38 fambox 50mounted-tests: debug: mounted using GRUB ntfs filesystem driver
Jan 21 08:17:38 fambox 50mounted-tests: debug: running subtest /usr/lib/os-probes/mounted/10freedos
Jan 21 08:17:38 fambox 10freedos: debug: /dev/sda1 is not a FAT partition: exiting
Jan 21 08:17:38 fambox 50mounted-tests: debug: running subtest /usr/lib/os-probes/mounted/10qnx
Jan 21 08:17:38 fambox 10qnx: debug: /dev/sda1 is not a QNX4 partition: exiting
Jan 21 08:17:38 fambox 50mounted-tests: debug: running subtest /usr/lib/os-probes/mounted/20macosx
Jan 21 08:17:38 fambox macosx-prober: debug: /dev/sda1 is not an HFS+ partition: exiting
Jan 21 08:17:38 fambox 50mounted-tests: debug: running subtest /usr/lib/os-probes/mounted/20microsoft
Jan 21 08:17:38 fambox 20microsoft: debug: /dev/sda1 is a NTFS partition
Jan 21 08:17:38 fambox 20microsoft: result: /dev/sda1:Windows 7 (loader):Windows:chain
Jan 21 08:17:38 fambox 50mounted-tests: debug: os found by subtest /usr/lib/os-probes/mounted/20microsoft
Jan 21 08:17:38 fambox os-prober: debug: os detected by /usr/lib/os-probes/50mounted-tests
Jan 21 08:17:38 fambox os-prober: debug: running /usr/lib/os-probes/mounted/10freedos on mounted /dev/sda2
Jan 21 08:17:38 fambox 10freedos: debug: /dev/sda2 is not a FAT partition: exiting
Jan 21 08:17:38 fambox os-prober: debug: running /usr/lib/os-probes/mounted/10qnx on mounted /dev/sda2
Jan 21 08:17:38 fambox 10qnx: debug: /dev/sda2 is not a QNX4 partition: exiting
Jan 21 08:17:38 fambox os-prober: debug: running /usr/lib/os-probes/mounted/20macosx on mounted /dev/sda2
Jan 21 08:17:38 fambox macosx-prober: debug: /dev/sda2 is not an HFS+ partition: exiting
Jan 21 08:17:38 fambox os-prober: debug: running /usr/lib/os-probes/mounted/20microsoft on mounted /dev/sda2
Jan 21 08:17:38 fambox 20microsoft: debug: /dev/sda2 is a FUSE partition
Jan 21 08:17:38 fambox os-prober: debug: running /usr/lib/os-probes/mounted/30utility on mounted /dev/sda2
Jan 21 08:17:38 fambox 30utility: debug: /dev/sda2 is not a FAT partition: exiting
Jan 21 08:17:38 fambox os-prober: debug: running /usr/lib/os-probes/mounted/40lsb on mounted /dev/sda2
Jan 21 08:17:38 fambox os-prober: debug: running /usr/lib/os-probes/mounted/70hurd on mounted /dev/sda2
Jan 21 08:17:38 fambox os-prober: debug: running /usr/lib/os-probes/mounted/80minix on mounted /dev/sda2
Jan 21 08:17:38 fambox os-prober: debug: running /usr/lib/os-probes/mounted/83haiku on mounted /dev/sda2
Jan 21 08:17:38 fambox 83haiku: debug: /dev/sda2 is not a BeFS partition: exiting
Jan 21 08:17:38 fambox os-prober: debug: running /usr/lib/os-probes/mounted/90bsd-distro on mounted /dev/sda2
Jan 21 08:17:38 fambox os-prober: debug: running /usr/lib/os-probes/mounted/90linux-distro on mounted /dev/sda2
Jan 21 08:17:38 fambox os-prober: debug: running /usr/lib/os-probes/mounted/90solaris on mounted /dev/sda2
Jan 21 08:17:38 fambox os-prober: debug: running /usr/lib/os-probes/50mounted-tests on /dev/sda3
Jan 21 08:17:38 fambox 50mounted-tests: debug: mounted using GRUB ntfs filesystem driver
Jan 21 08:17:38 fambox 50mounted-tests: debug: running subtest /usr/lib/os-probes/mounted/10freedos
Jan 21 08:17:38 fambox 10freedos: debug: /dev/sda3 is not a FAT partition: exiting
Jan 21 08:17:38 fambox 50mounted-tests: debug: running subtest /usr/lib/os-probes/mounted/10qnx
Jan 21 08:17:38 fambox 10qnx: debug: /dev/sda3 is not a QNX4 partition: exiting
Jan 21 08:17:38 fambox 50mounted-tests: debug: running subtest /usr/lib/os-probes/mounted/20macosx
Jan 21 08:17:38 fambox macosx-prober: debug: /dev/sda3 is not an HFS+ partition: exiting
Jan 21 08:17:38 fambox 50mounted-tests: debug: running subtest /usr/lib/os-probes/mounted/20microsoft
Jan 21 08:17:38 fambox 20microsoft: debug: /dev/sda3 is a NTFS partition
Jan 21 08:17:39 fambox 20microsoft: result: /dev/sda3:Windows Recovery Environment (loader):Windows1:chain
Jan 21 08:17:39 fambox 50mounted-tests: debug: os found by subtest /usr/lib/os-probes/mounted/20microsoft
Jan 21 08:17:39 fambox os-prober: debug: os detected by /usr/lib/os-probes/50mounted-tests
Jan 21 08:17:39 fambox os-prober: debug: running /usr/lib/os-probes/50mounted-tests on /dev/sdb1
Jan 21 08:17:39 fambox 50mounted-tests: debug: /dev/sdb1 type not recognised; skipping
Jan 21 08:17:39 fambox os-prober: debug: os detected by /usr/lib/os-probes/50mounted-tests
Jan 21 08:17:39 fambox os-prober: debug: running /usr/lib/os-probes/50mounted-tests on /dev/sdb2
Jan 21 08:17:39 fambox 50mounted-tests: debug: /dev/sdb2 type not recognised; skipping
Jan 21 08:17:39 fambox os-prober: debug: os detected by /usr/lib/os-probes/50mounted-tests
Jan 21 08:18:25 fambox kernel: [ 659.450269] PM: Syncing filesystems ... done.
Jan 21 08:18:25 fambox kernel: [ 659.560807] PM: Preparing system for mem sleep
Jan 21 08:18:52 fambox kernel: [ 666.004376] Freezing user space processes ...
Jan 21 08:18:52 fambox kernel: [ 686.014794] Freezing of tasks failed after 20.01 seconds (1 tasks refusing to freeze, wq_busy=0):
Jan 21 08:18:52 fambox kernel: [ 686.014926] cupsd D ffffffff8180d780 0 1044 1 0x00000004
Jan 21 08:18:52 fambox kernel: [ 686.014935] ffff880101a7be18 0000000000000046 ffff880101a7bdc8 0000000300000001
Jan 21 08:18:52 fambox kernel: [ 686.014944] ffff8801181b4560 ffff880101a7bfd8 ffff880101a7bfd8 ffff880101a7bfd8
Jan 21 08:18:52 fambox kernel: [ 686.014951] ffffffff81c15440 ffff8801181b4560 ffff880101a7be28 ffff88011857f800
Jan 21 08:18:52 fambox kernel: [ 686.014958] Call Trace:
Jan 21 08:18:52 fambox kernel: [ 686.014973] [<ffffffff816b7e39>] schedule+0x29/0x70
Jan 21 08:18:52 fambox kernel: [ 686.014985] [<ffffffff8128fdad>] jbd2_log_wait_commit+0xcd/0x1a0
Jan 21 08:18:52 fambox kernel: [ 686.014993] [<ffffffff8107eb90>] ? add_wait_queue+0x60/0x60
Jan 21 08:18:52 fambox kernel: [ 686.015001] [<ffffffff8122fed5>] ext4_sync_file+0x205/0x380
Jan 21 08:18:52 fambox kernel: [ 686.015009] [<ffffffff811c372d>] do_fsync+0x5d/0x90
Jan 21 08:18:52 fambox kernel: [ 686.015018] [<ffffffff81193792>] ? sys_write+0x52/0xa0
Jan 21 08:18:52 fambox kernel: [ 686.015024] [<ffffffff811c3b10>] sys_fsync+0x10/0x20
Jan 21 08:18:52 fambox kernel: [ 686.015031] [<ffffffff816c189d>] system_call_fastpath+0x1a/0x1f
Jan 21 08:18:52 fambox kernel: [ 686.015093]
Jan 21 08:18:52 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:18:52 fambox rtkit-daemon[1808]: The canary thread is apparently starving. Taking action.
Jan 21 08:18:52 fambox rtkit-daemon[1808]: Demoting known real-time threads.
Jan 21 08:18:52 fambox rtkit-daemon[1808]: Successfully demoted thread 1972 of process 1968 (n/a).
Jan 21 08:18:52 fambox rtkit-daemon[1808]: Successfully demoted thread 1969 of process 1968 (n/a).
Jan 21 08:18:52 fambox rtkit-daemon[1808]: Successfully demoted thread 1968 of process 1968 (n/a).
Jan 21 08:18:52 fambox rtkit-daemon[1808]: Demoted 3 threads.
Jan 21 08:18:52 fambox kernel: [ 686.015096] Restarting tasks ... done.
Jan 21 08:18:52 fambox kernel: [ 686.024031] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:18:52 fambox acpid: client connected from 1254[0:0]
Jan 21 08:18:52 fambox acpid: 1 client rule loaded
Jan 21 08:18:52 fambox kernel: [ 686.024594] PM: Syncing filesystems ... done.
Jan 21 08:18:52 fambox kernel: [ 686.528387] PM: Preparing system for mem sleep
Jan 21 08:19:00 fambox kernel: [ 689.389593] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:19:00 fambox kernel: [ 689.406076] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:19:00 fambox kernel: [ 689.422109] suspend debug: Waiting for 5 seconds.
Jan 21 08:19:00 fambox kernel: [ 694.378815] PM: Finishing wakeup.
Jan 21 08:19:00 fambox kernel: [ 694.378817] Restarting tasks ... done.
Jan 21 08:19:00 fambox kernel: [ 694.386261] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:19:00 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:19:00 fambox acpid: client connected from 1254[0:0]
Jan 21 08:19:00 fambox acpid: 1 client rule loaded
Jan 21 08:19:01 fambox kernel: [ 695.388216] PM: Syncing filesystems ... done.
Jan 21 08:19:01 fambox kernel: [ 695.669009] PM: Preparing system for mem sleep
Jan 21 08:19:09 fambox kernel: [ 698.663894] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:19:09 fambox kernel: [ 698.680202] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:19:09 fambox kernel: [ 698.696290] suspend debug: Waiting for 5 seconds.
Jan 21 08:19:09 fambox kernel: [ 703.652954] PM: Finishing wakeup.
Jan 21 08:19:09 fambox kernel: [ 703.652956] Restarting tasks ... done.
Jan 21 08:19:09 fambox kernel: [ 703.657023] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:19:09 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:19:09 fambox acpid: client connected from 1254[0:0]
Jan 21 08:19:09 fambox acpid: 1 client rule loaded
Jan 21 08:19:11 fambox kernel: [ 704.658252] PM: Syncing filesystems ... done.
Jan 21 08:19:11 fambox kernel: [ 704.773724] PM: Preparing system for mem sleep
Jan 21 08:19:36 fambox kernel: [ 709.879880] Freezing user space processes ... (elapsed 0.06 seconds) done.
Jan 21 08:19:36 fambox kernel: [ 709.944282] Freezing remaining freezable tasks ...
Jan 21 08:19:36 fambox kernel: [ 729.946099] Freezing of tasks failed after 20.01 seconds (1 tasks refusing to freeze, wq_busy=0):
Jan 21 08:19:36 fambox kernel: [ 729.946222] jbd2/loop0-8 D ffffffff8180d780 0 311 2 0x00000000
Jan 21 08:19:36 fambox kernel: [ 729.946231] ffff880115353b68 0000000000000046 ffff8801180f1720 0000000000000001
Jan 21 08:19:36 fambox kernel: [ 729.946240] ffff8801180f1720 ffff880115353fd8 ffff880115353fd8 ffff880115353fd8
Jan 21 08:19:36 fambox kernel: [ 729.946246] ffff880119b32e40 ffff8801180f1720 ffff880115353b68 ffff88011fa94738
Jan 21 08:19:36 fambox kernel: [ 729.946253] Call Trace:
Jan 21 08:19:36 fambox kernel: [ 729.946271] [<ffffffff811c5bb0>] ? __wait_on_buffer+0x30/0x30
Jan 21 08:19:36 fambox kernel: [ 729.946279] [<ffffffff816b7e39>] schedule+0x29/0x70
Jan 21 08:19:36 fambox kernel: [ 729.946285] [<ffffffff816b7f0f>] io_schedule+0x8f/0xd0
Jan 21 08:19:36 fambox kernel: [ 729.946292] [<ffffffff811c5bbe>] sleep_on_buffer+0xe/0x20
Jan 21 08:19:36 fambox kernel: [ 729.946301] [<ffffffff816b670f>] __wait_on_bit+0x5f/0x90
Jan 21 08:19:36 fambox kernel: [ 729.946308] [<ffffffff811c5271>] ? submit_bh+0x121/0x1e0
Jan 21 08:19:36 fambox kernel: [ 729.946315] [<ffffffff811c5bb0>] ? __wait_on_buffer+0x30/0x30
Jan 21 08:19:36 fambox kernel: [ 729.946323] [<ffffffff816b67bc>] out_of_line_wait_on_bit+0x7c/0x90
Jan 21 08:19:36 fambox kernel: [ 729.946331] [<ffffffff8107ebd0>] ? autoremove_wake_function+0x40/0x40
Jan 21 08:19:36 fambox kernel: [ 729.946338] [<ffffffff811c5bae>] __wait_on_buffer+0x2e/0x30
Jan 21 08:19:36 fambox kernel: [ 729.946347] [<ffffffff8128b75c>] jbd2_journal_commit_transaction+0x18cc/0x1d60
Jan 21 08:19:36 fambox kernel: [ 729.946355] [<ffffffff81093d78>] ? set_next_entity+0xa8/0xc0
Jan 21 08:19:36 fambox kernel: [ 729.946362] [<ffffffff816b8fce>] ? _raw_spin_lock_irqsave+0x2e/0x40
Jan 21 08:19:36 fambox kernel: [ 729.946370] [<ffffffff81069fcf>] ? try_to_del_timer_sync+0x4f/0x70
Jan 21 08:19:36 fambox kernel: [ 729.946380] [<ffffffff8128ff66>] kjournald2+0xd6/0x3e0
Jan 21 08:19:36 fambox kernel: [ 729.946386] [<ffffffff8107eb90>] ? add_wait_queue+0x60/0x60
Jan 21 08:19:36 fambox kernel: [ 729.946394] [<ffffffff8128fe90>] ? commit_timeout+0x10/0x10
Jan 21 08:19:36 fambox kernel: [ 729.946399] [<ffffffff8107dfa0>] kthread+0xc0/0xd0
Jan 21 08:19:36 fambox kernel: [ 729.946405] [<ffffffff8107dee0>] ? flush_kthread_worker+0xb0/0xb0
Jan 21 08:19:36 fambox kernel: [ 729.946412] [<ffffffff816c17ec>] ret_from_fork+0x7c/0xb0
Jan 21 08:19:36 fambox kernel: [ 729.946418] [<ffffffff8107dee0>] ? flush_kthread_worker+0xb0/0xb0
Jan 21 08:19:36 fambox kernel: [ 729.946481]
Jan 21 08:19:36 fambox kernel: [ 729.946484] Restarting kernel threads ... done.
Jan 21 08:19:36 fambox rtkit-daemon[1808]: The canary thread is apparently starving. Taking action.
Jan 21 08:19:36 fambox rtkit-daemon[1808]: Demoting known real-time threads.
Jan 21 08:19:36 fambox rtkit-daemon[1808]: Successfully demoted thread 1972 of process 1968 (n/a).
Jan 21 08:19:36 fambox rtkit-daemon[1808]: Successfully demoted thread 1969 of process 1968 (n/a).
Jan 21 08:19:36 fambox rtkit-daemon[1808]: Successfully demoted thread 1968 of process 1968 (n/a).
Jan 21 08:19:36 fambox rtkit-daemon[1808]: Demoted 3 threads.
Jan 21 08:19:36 fambox kernel: [ 729.946638] Restarting tasks ... done.
Jan 21 08:19:36 fambox kernel: [ 729.957292] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:19:36 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:19:36 fambox acpid: client connected from 1254[0:0]
Jan 21 08:19:36 fambox acpid: 1 client rule loaded
Jan 21 08:19:36 fambox kernel: [ 729.957655] PM: Syncing filesystems ... done.
Jan 21 08:19:36 fambox kernel: [ 730.090702] PM: Preparing system for mem sleep
Jan 21 08:19:46 fambox kernel: [ 735.049968] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:19:46 fambox kernel: [ 735.066344] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:19:46 fambox kernel: [ 735.082470] suspend debug: Waiting for 5 seconds.
Jan 21 08:19:46 fambox kernel: [ 740.039150] PM: Finishing wakeup.
Jan 21 08:19:46 fambox rtkit-daemon[1808]: The canary thread is apparently starving. Taking action.
Jan 21 08:19:46 fambox rtkit-daemon[1808]: Demoting known real-time threads.
Jan 21 08:19:46 fambox rtkit-daemon[1808]: Successfully demoted thread 1972 of process 1968 (n/a).
Jan 21 08:19:46 fambox rtkit-daemon[1808]: Successfully demoted thread 1969 of process 1968 (n/a).
Jan 21 08:19:46 fambox rtkit-daemon[1808]: Successfully demoted thread 1968 of process 1968 (n/a).
Jan 21 08:19:46 fambox rtkit-daemon[1808]: Demoted 3 threads.
Jan 21 08:19:46 fambox kernel: [ 740.039152] Restarting tasks ... done.
Jan 21 08:19:46 fambox kernel: [ 740.044754] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:19:46 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:19:46 fambox acpid: client connected from 1254[0:0]
Jan 21 08:19:46 fambox acpid: 1 client rule loaded
Jan 21 08:19:47 fambox kernel: [ 741.047618] PM: Syncing filesystems ... done.
Jan 21 08:19:47 fambox kernel: [ 741.144638] PM: Preparing system for mem sleep
Jan 21 08:20:12 fambox kernel: [ 746.474101] Freezing user space processes ... (elapsed 0.04 seconds) done.
Jan 21 08:20:12 fambox kernel: [ 746.522356] Freezing remaining freezable tasks ...
Jan 21 08:20:12 fambox kernel: [ 766.524155] Freezing of tasks failed after 20.01 seconds (1 tasks refusing to freeze, wq_busy=0):
Jan 21 08:20:12 fambox kernel: [ 766.524280] jbd2/loop0-8 D ffffffff8180d780 0 311 2 0x00000000
Jan 21 08:20:12 fambox kernel: [ 766.524289] ffff880115353b68 0000000000000046 ffff880115353b08 ffffffff81044c29
Jan 21 08:20:12 fambox kernel: [ 766.524297] ffff8801180f1720 ffff880115353fd8 ffff880115353fd8 ffff880115353fd8
Jan 21 08:20:12 fambox kernel: [ 766.524304] ffff880119b32e40 ffff8801180f1720 ffff880115353b68 ffff88011fa94738
Jan 21 08:20:12 fambox kernel: [ 766.524311] Call Trace:
Jan 21 08:20:12 fambox kernel: [ 766.524330] [<ffffffff81044c29>] ? default_spin_lock_flags+0x9/0x10
Jan 21 08:20:12 fambox kernel: [ 766.524340] [<ffffffff811c5bb0>] ? __wait_on_buffer+0x30/0x30
Jan 21 08:20:12 fambox kernel: [ 766.524349] [<ffffffff816b7e39>] schedule+0x29/0x70
Jan 21 08:20:12 fambox kernel: [ 766.524355] [<ffffffff816b7f0f>] io_schedule+0x8f/0xd0
Jan 21 08:20:12 fambox kernel: [ 766.524361] [<ffffffff811c5bbe>] sleep_on_buffer+0xe/0x20
Jan 21 08:20:12 fambox kernel: [ 766.524371] [<ffffffff816b670f>] __wait_on_bit+0x5f/0x90
Jan 21 08:20:12 fambox kernel: [ 766.524378] [<ffffffff811c5271>] ? submit_bh+0x121/0x1e0
Jan 21 08:20:12 fambox kernel: [ 766.524384] [<ffffffff811c5bb0>] ? __wait_on_buffer+0x30/0x30
Jan 21 08:20:12 fambox kernel: [ 766.524392] [<ffffffff816b67bc>] out_of_line_wait_on_bit+0x7c/0x90
Jan 21 08:20:12 fambox kernel: [ 766.524400] [<ffffffff8107ebd0>] ? autoremove_wake_function+0x40/0x40
Jan 21 08:20:12 fambox kernel: [ 766.524407] [<ffffffff811c5bae>] __wait_on_buffer+0x2e/0x30
Jan 21 08:20:12 fambox kernel: [ 766.524417] [<ffffffff8128b75c>] jbd2_journal_commit_transaction+0x18cc/0x1d60
Jan 21 08:20:12 fambox kernel: [ 766.524425] [<ffffffff816b8fce>] ? _raw_spin_lock_irqsave+0x2e/0x40
Jan 21 08:20:12 fambox kernel: [ 766.524434] [<ffffffff81069fcf>] ? try_to_del_timer_sync+0x4f/0x70
Jan 21 08:20:12 fambox kernel: [ 766.524444] [<ffffffff8128ff66>] kjournald2+0xd6/0x3e0
Jan 21 08:20:12 fambox kernel: [ 766.524450] [<ffffffff8107eb90>] ? add_wait_queue+0x60/0x60
Jan 21 08:20:12 fambox kernel: [ 766.524458] [<ffffffff8128fe90>] ? commit_timeout+0x10/0x10
Jan 21 08:20:12 fambox kernel: [ 766.524463] [<ffffffff8107dfa0>] kthread+0xc0/0xd0
Jan 21 08:20:12 fambox kernel: [ 766.524469] [<ffffffff8107dee0>] ? flush_kthread_worker+0xb0/0xb0
Jan 21 08:20:12 fambox kernel: [ 766.524477] [<ffffffff816c17ec>] ret_from_fork+0x7c/0xb0
Jan 21 08:20:12 fambox kernel: [ 766.524482] [<ffffffff8107dee0>] ? flush_kthread_worker+0xb0/0xb0
Jan 21 08:20:12 fambox kernel: [ 766.524549]
Jan 21 08:20:12 fambox kernel: [ 766.524552] Restarting kernel threads ... done.
Jan 21 08:20:12 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:20:12 fambox rtkit-daemon[1808]: The canary thread is apparently starving. Taking action.
Jan 21 08:20:12 fambox rtkit-daemon[1808]: Demoting known real-time threads.
Jan 21 08:20:12 fambox rtkit-daemon[1808]: Successfully demoted thread 1972 of process 1968 (n/a).
Jan 21 08:20:12 fambox rtkit-daemon[1808]: Successfully demoted thread 1969 of process 1968 (n/a).
Jan 21 08:20:12 fambox rtkit-daemon[1808]: Successfully demoted thread 1968 of process 1968 (n/a).
Jan 21 08:20:12 fambox rtkit-daemon[1808]: Demoted 3 threads.
Jan 21 08:20:12 fambox kernel: [ 766.524709] Restarting tasks ... done.
Jan 21 08:20:12 fambox kernel: [ 766.536532] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:20:12 fambox acpid: client connected from 1254[0:0]
Jan 21 08:20:12 fambox acpid: 1 client rule loaded
Jan 21 08:20:13 fambox kernel: [ 766.537083] PM: Syncing filesystems ... done.
Jan 21 08:20:13 fambox kernel: [ 766.787883] PM: Preparing system for mem sleep
Jan 21 08:20:19 fambox kernel: [ 768.478192] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:20:19 fambox kernel: [ 768.494712] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:20:19 fambox kernel: [ 768.510734] suspend debug: Waiting for 5 seconds.
Jan 21 08:20:19 fambox kernel: [ 773.467417] PM: Finishing wakeup.
Jan 21 08:20:19 fambox kernel: [ 773.467420] Restarting tasks ... done.
Jan 21 08:20:19 fambox kernel: [ 773.472865] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:20:19 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:20:19 fambox acpid: client connected from 1254[0:0]
Jan 21 08:20:19 fambox acpid: 1 client rule loaded
Jan 21 08:20:20 fambox kernel: [ 774.477386] PM: Syncing filesystems ... done.
Jan 21 08:20:20 fambox kernel: [ 774.593585] PM: Preparing system for mem sleep
Jan 21 08:20:30 fambox kernel: [ 778.647805] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:20:30 fambox kernel: [ 778.663513] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:20:30 fambox kernel: [ 778.679553] suspend debug: Waiting for 5 seconds.
Jan 21 08:20:30 fambox kernel: [ 783.636254] PM: Finishing wakeup.
Jan 21 08:20:30 fambox rtkit-daemon[1808]: The canary thread is apparently starving. Taking action.
Jan 21 08:20:30 fambox rtkit-daemon[1808]: Demoting known real-time threads.
Jan 21 08:20:30 fambox rtkit-daemon[1808]: Successfully demoted thread 1972 of process 1968 (n/a).
Jan 21 08:20:30 fambox rtkit-daemon[1808]: Successfully demoted thread 1969 of process 1968 (n/a).
Jan 21 08:20:30 fambox rtkit-daemon[1808]: Successfully demoted thread 1968 of process 1968 (n/a).
Jan 21 08:20:30 fambox rtkit-daemon[1808]: Demoted 3 threads.
Jan 21 08:20:30 fambox kernel: [ 783.636256] Restarting tasks ... done.
Jan 21 08:20:30 fambox kernel: [ 783.641310] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:20:30 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:20:30 fambox acpid: client connected from 1254[0:0]
Jan 21 08:20:30 fambox acpid: 1 client rule loaded
Jan 21 08:20:31 fambox kernel: [ 784.643646] PM: Syncing filesystems ... done.
Jan 21 08:20:31 fambox kernel: [ 784.917006] PM: Preparing system for mem sleep
Jan 21 08:20:41 fambox kernel: [ 790.494656] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:20:41 fambox kernel: [ 790.511009] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:20:41 fambox kernel: [ 790.527184] suspend debug: Waiting for 5 seconds.
Jan 21 08:20:41 fambox kernel: [ 795.483884] PM: Finishing wakeup.
Jan 21 08:20:41 fambox kernel: [ 795.483885] Restarting tasks ... done.
Jan 21 08:20:41 fambox kernel: [ 795.490986] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:20:41 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:20:41 fambox acpid: client connected from 1254[0:0]
Jan 21 08:20:41 fambox acpid: 1 client rule loaded
Jan 21 08:20:43 fambox kernel: [ 796.494290] PM: Syncing filesystems ... done.
Jan 21 08:20:43 fambox kernel: [ 796.622749] PM: Preparing system for mem sleep
Jan 21 08:20:54 fambox kernel: [ 802.917838] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:20:54 fambox kernel: [ 802.934348] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:20:54 fambox kernel: [ 802.950288] suspend debug: Waiting for 5 seconds.
Jan 21 08:20:54 fambox kernel: [ 807.907038] PM: Finishing wakeup.
Jan 21 08:20:54 fambox rtkit-daemon[1808]: The canary thread is apparently starving. Taking action.
Jan 21 08:20:54 fambox rtkit-daemon[1808]: Demoting known real-time threads.
Jan 21 08:20:54 fambox rtkit-daemon[1808]: Successfully demoted thread 1972 of process 1968 (n/a).
Jan 21 08:20:54 fambox rtkit-daemon[1808]: Successfully demoted thread 1969 of process 1968 (n/a).
Jan 21 08:20:54 fambox rtkit-daemon[1808]: Successfully demoted thread 1968 of process 1968 (n/a).
Jan 21 08:20:54 fambox rtkit-daemon[1808]: Demoted 3 threads.
Jan 21 08:20:54 fambox kernel: [ 807.907040] Restarting tasks ... done.
Jan 21 08:20:54 fambox kernel: [ 807.915538] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:20:54 fambox acpid: client 1254[0:0] has disconnected
Jan 21 08:20:54 fambox acpid: client connected from 1254[0:0]
Jan 21 08:20:54 fambox acpid: 1 client rule loaded
Jan 21 08:22:18 fambox kernel: [ 892.419318] type=1400 audit(1358752938.864:24): apparmor="DENIED" operation="capable" parent=1 profile="/usr/sbin/cupsd" pid=1044 comm="cupsd" pid=1044 comm="cupsd" capability=36 capname="block_suspend"
[-- Attachment #3: dmesg_freezer-pm-test-2.diff --]
[-- Type: application/octet-stream, Size: 9522 bytes --]
--- dmesg_3.8.0-rc4-next20130121-1-iniza-generic_freezer-pm-test.txt 2013-01-21 08:15:18.154405943 +0100
+++ dmesg_3.8.0-rc4-next20130121-1-iniza-generic_freezer-pm-test-2.txt 2013-01-21 08:21:16.264806220 +0100
@@ -953,3 +953,151 @@
[ 451.925556] PM: Finishing wakeup.
[ 451.925558] Restarting tasks ... done.
[ 451.930859] video LNXVIDEO:00: Restoring backlight state
+[ 611.195107] SGI XFS with ACLs, security attributes, realtime, large block/inode numbers, no debug enabled
+[ 611.276930] Btrfs loaded
+[ 659.450269] PM: Syncing filesystems ... done.
+[ 659.560807] PM: Preparing system for mem sleep
+[ 666.004376] Freezing user space processes ...
+[ 686.014794] Freezing of tasks failed after 20.01 seconds (1 tasks refusing to freeze, wq_busy=0):
+[ 686.014926] cupsd D ffffffff8180d780 0 1044 1 0x00000004
+[ 686.014935] ffff880101a7be18 0000000000000046 ffff880101a7bdc8 0000000300000001
+[ 686.014944] ffff8801181b4560 ffff880101a7bfd8 ffff880101a7bfd8 ffff880101a7bfd8
+[ 686.014951] ffffffff81c15440 ffff8801181b4560 ffff880101a7be28 ffff88011857f800
+[ 686.014958] Call Trace:
+[ 686.014973] [<ffffffff816b7e39>] schedule+0x29/0x70
+[ 686.014985] [<ffffffff8128fdad>] jbd2_log_wait_commit+0xcd/0x1a0
+[ 686.014993] [<ffffffff8107eb90>] ? add_wait_queue+0x60/0x60
+[ 686.015001] [<ffffffff8122fed5>] ext4_sync_file+0x205/0x380
+[ 686.015009] [<ffffffff811c372d>] do_fsync+0x5d/0x90
+[ 686.015018] [<ffffffff81193792>] ? sys_write+0x52/0xa0
+[ 686.015024] [<ffffffff811c3b10>] sys_fsync+0x10/0x20
+[ 686.015031] [<ffffffff816c189d>] system_call_fastpath+0x1a/0x1f
+[ 686.015093]
+[ 686.015096] Restarting tasks ... done.
+[ 686.024031] video LNXVIDEO:00: Restoring backlight state
+[ 686.024594] PM: Syncing filesystems ... done.
+[ 686.528387] PM: Preparing system for mem sleep
+[ 689.389593] Freezing user space processes ... (elapsed 0.01 seconds) done.
+[ 689.406076] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
+[ 689.422109] suspend debug: Waiting for 5 seconds.
+[ 694.378815] PM: Finishing wakeup.
+[ 694.378817] Restarting tasks ... done.
+[ 694.386261] video LNXVIDEO:00: Restoring backlight state
+[ 695.388216] PM: Syncing filesystems ... done.
+[ 695.669009] PM: Preparing system for mem sleep
+[ 698.663894] Freezing user space processes ... (elapsed 0.01 seconds) done.
+[ 698.680202] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
+[ 698.696290] suspend debug: Waiting for 5 seconds.
+[ 703.652954] PM: Finishing wakeup.
+[ 703.652956] Restarting tasks ... done.
+[ 703.657023] video LNXVIDEO:00: Restoring backlight state
+[ 704.658252] PM: Syncing filesystems ... done.
+[ 704.773724] PM: Preparing system for mem sleep
+[ 709.879880] Freezing user space processes ... (elapsed 0.06 seconds) done.
+[ 709.944282] Freezing remaining freezable tasks ...
+[ 729.946099] Freezing of tasks failed after 20.01 seconds (1 tasks refusing to freeze, wq_busy=0):
+[ 729.946222] jbd2/loop0-8 D ffffffff8180d780 0 311 2 0x00000000
+[ 729.946231] ffff880115353b68 0000000000000046 ffff8801180f1720 0000000000000001
+[ 729.946240] ffff8801180f1720 ffff880115353fd8 ffff880115353fd8 ffff880115353fd8
+[ 729.946246] ffff880119b32e40 ffff8801180f1720 ffff880115353b68 ffff88011fa94738
+[ 729.946253] Call Trace:
+[ 729.946271] [<ffffffff811c5bb0>] ? __wait_on_buffer+0x30/0x30
+[ 729.946279] [<ffffffff816b7e39>] schedule+0x29/0x70
+[ 729.946285] [<ffffffff816b7f0f>] io_schedule+0x8f/0xd0
+[ 729.946292] [<ffffffff811c5bbe>] sleep_on_buffer+0xe/0x20
+[ 729.946301] [<ffffffff816b670f>] __wait_on_bit+0x5f/0x90
+[ 729.946308] [<ffffffff811c5271>] ? submit_bh+0x121/0x1e0
+[ 729.946315] [<ffffffff811c5bb0>] ? __wait_on_buffer+0x30/0x30
+[ 729.946323] [<ffffffff816b67bc>] out_of_line_wait_on_bit+0x7c/0x90
+[ 729.946331] [<ffffffff8107ebd0>] ? autoremove_wake_function+0x40/0x40
+[ 729.946338] [<ffffffff811c5bae>] __wait_on_buffer+0x2e/0x30
+[ 729.946347] [<ffffffff8128b75c>] jbd2_journal_commit_transaction+0x18cc/0x1d60
+[ 729.946355] [<ffffffff81093d78>] ? set_next_entity+0xa8/0xc0
+[ 729.946362] [<ffffffff816b8fce>] ? _raw_spin_lock_irqsave+0x2e/0x40
+[ 729.946370] [<ffffffff81069fcf>] ? try_to_del_timer_sync+0x4f/0x70
+[ 729.946380] [<ffffffff8128ff66>] kjournald2+0xd6/0x3e0
+[ 729.946386] [<ffffffff8107eb90>] ? add_wait_queue+0x60/0x60
+[ 729.946394] [<ffffffff8128fe90>] ? commit_timeout+0x10/0x10
+[ 729.946399] [<ffffffff8107dfa0>] kthread+0xc0/0xd0
+[ 729.946405] [<ffffffff8107dee0>] ? flush_kthread_worker+0xb0/0xb0
+[ 729.946412] [<ffffffff816c17ec>] ret_from_fork+0x7c/0xb0
+[ 729.946418] [<ffffffff8107dee0>] ? flush_kthread_worker+0xb0/0xb0
+[ 729.946481]
+[ 729.946484] Restarting kernel threads ... done.
+[ 729.946638] Restarting tasks ... done.
+[ 729.957292] video LNXVIDEO:00: Restoring backlight state
+[ 729.957655] PM: Syncing filesystems ... done.
+[ 730.090702] PM: Preparing system for mem sleep
+[ 735.049968] Freezing user space processes ... (elapsed 0.01 seconds) done.
+[ 735.066344] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
+[ 735.082470] suspend debug: Waiting for 5 seconds.
+[ 740.039150] PM: Finishing wakeup.
+[ 740.039152] Restarting tasks ... done.
+[ 740.044754] video LNXVIDEO:00: Restoring backlight state
+[ 741.047618] PM: Syncing filesystems ... done.
+[ 741.144638] PM: Preparing system for mem sleep
+[ 746.474101] Freezing user space processes ... (elapsed 0.04 seconds) done.
+[ 746.522356] Freezing remaining freezable tasks ...
+[ 766.524155] Freezing of tasks failed after 20.01 seconds (1 tasks refusing to freeze, wq_busy=0):
+[ 766.524280] jbd2/loop0-8 D ffffffff8180d780 0 311 2 0x00000000
+[ 766.524289] ffff880115353b68 0000000000000046 ffff880115353b08 ffffffff81044c29
+[ 766.524297] ffff8801180f1720 ffff880115353fd8 ffff880115353fd8 ffff880115353fd8
+[ 766.524304] ffff880119b32e40 ffff8801180f1720 ffff880115353b68 ffff88011fa94738
+[ 766.524311] Call Trace:
+[ 766.524330] [<ffffffff81044c29>] ? default_spin_lock_flags+0x9/0x10
+[ 766.524340] [<ffffffff811c5bb0>] ? __wait_on_buffer+0x30/0x30
+[ 766.524349] [<ffffffff816b7e39>] schedule+0x29/0x70
+[ 766.524355] [<ffffffff816b7f0f>] io_schedule+0x8f/0xd0
+[ 766.524361] [<ffffffff811c5bbe>] sleep_on_buffer+0xe/0x20
+[ 766.524371] [<ffffffff816b670f>] __wait_on_bit+0x5f/0x90
+[ 766.524378] [<ffffffff811c5271>] ? submit_bh+0x121/0x1e0
+[ 766.524384] [<ffffffff811c5bb0>] ? __wait_on_buffer+0x30/0x30
+[ 766.524392] [<ffffffff816b67bc>] out_of_line_wait_on_bit+0x7c/0x90
+[ 766.524400] [<ffffffff8107ebd0>] ? autoremove_wake_function+0x40/0x40
+[ 766.524407] [<ffffffff811c5bae>] __wait_on_buffer+0x2e/0x30
+[ 766.524417] [<ffffffff8128b75c>] jbd2_journal_commit_transaction+0x18cc/0x1d60
+[ 766.524425] [<ffffffff816b8fce>] ? _raw_spin_lock_irqsave+0x2e/0x40
+[ 766.524434] [<ffffffff81069fcf>] ? try_to_del_timer_sync+0x4f/0x70
+[ 766.524444] [<ffffffff8128ff66>] kjournald2+0xd6/0x3e0
+[ 766.524450] [<ffffffff8107eb90>] ? add_wait_queue+0x60/0x60
+[ 766.524458] [<ffffffff8128fe90>] ? commit_timeout+0x10/0x10
+[ 766.524463] [<ffffffff8107dfa0>] kthread+0xc0/0xd0
+[ 766.524469] [<ffffffff8107dee0>] ? flush_kthread_worker+0xb0/0xb0
+[ 766.524477] [<ffffffff816c17ec>] ret_from_fork+0x7c/0xb0
+[ 766.524482] [<ffffffff8107dee0>] ? flush_kthread_worker+0xb0/0xb0
+[ 766.524549]
+[ 766.524552] Restarting kernel threads ... done.
+[ 766.524709] Restarting tasks ... done.
+[ 766.536532] video LNXVIDEO:00: Restoring backlight state
+[ 766.537083] PM: Syncing filesystems ... done.
+[ 766.787883] PM: Preparing system for mem sleep
+[ 768.478192] Freezing user space processes ... (elapsed 0.01 seconds) done.
+[ 768.494712] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
+[ 768.510734] suspend debug: Waiting for 5 seconds.
+[ 773.467417] PM: Finishing wakeup.
+[ 773.467420] Restarting tasks ... done.
+[ 773.472865] video LNXVIDEO:00: Restoring backlight state
+[ 774.477386] PM: Syncing filesystems ... done.
+[ 774.593585] PM: Preparing system for mem sleep
+[ 778.647805] Freezing user space processes ... (elapsed 0.01 seconds) done.
+[ 778.663513] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
+[ 778.679553] suspend debug: Waiting for 5 seconds.
+[ 783.636254] PM: Finishing wakeup.
+[ 783.636256] Restarting tasks ... done.
+[ 783.641310] video LNXVIDEO:00: Restoring backlight state
+[ 784.643646] PM: Syncing filesystems ... done.
+[ 784.917006] PM: Preparing system for mem sleep
+[ 790.494656] Freezing user space processes ... (elapsed 0.01 seconds) done.
+[ 790.511009] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
+[ 790.527184] suspend debug: Waiting for 5 seconds.
+[ 795.483884] PM: Finishing wakeup.
+[ 795.483885] Restarting tasks ... done.
+[ 795.490986] video LNXVIDEO:00: Restoring backlight state
+[ 796.494290] PM: Syncing filesystems ... done.
+[ 796.622749] PM: Preparing system for mem sleep
+[ 802.917838] Freezing user space processes ... (elapsed 0.01 seconds) done.
+[ 802.934348] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
+[ 802.950288] suspend debug: Waiting for 5 seconds.
+[ 807.907038] PM: Finishing wakeup.
+[ 807.907040] Restarting tasks ... done.
+[ 807.915538] video LNXVIDEO:00: Restoring backlight state
[-- Attachment #4: run_pm-test.sh --]
[-- Type: application/x-sh, Size: 1073 bytes --]
[-- Attachment #5: kern-log.txt --]
[-- Type: text/plain, Size: 29263 bytes --]
Jan 21 08:11:23 fambox kernel: [ 244.792739] wlan0: deauthenticating from 00:04:0e:e4:00:3d by local choice (reason=3)
Jan 21 08:11:23 fambox kernel: [ 244.806345] cfg80211: Calling CRDA to update world regulatory domain
Jan 21 08:11:24 fambox kernel: [ 244.816996] cfg80211: World regulatory domain updated:
Jan 21 08:11:24 fambox kernel: [ 244.817007] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
Jan 21 08:11:24 fambox kernel: [ 244.817013] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Jan 21 08:11:24 fambox kernel: [ 244.817018] cfg80211: (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
Jan 21 08:11:24 fambox kernel: [ 244.817021] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
Jan 21 08:11:24 fambox kernel: [ 244.817025] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Jan 21 08:11:24 fambox kernel: [ 244.817028] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Jan 21 08:11:25 fambox kernel: [ 246.688282] PM: Syncing filesystems ... done.
Jan 21 08:11:25 fambox kernel: [ 246.693207] PM: Preparing system for mem sleep
Jan 21 08:11:38 fambox kernel: [ 248.377923] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:11:38 fambox kernel: [ 248.393228] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:11:38 fambox kernel: [ 248.409192] PM: Entering mem sleep
Jan 21 08:11:38 fambox kernel: [ 248.409256] Suspending console(s) (use no_console_suspend to debug)
Jan 21 08:11:38 fambox kernel: [ 248.409485] sd 1:0:0:0: [sdb] Synchronizing SCSI cache
Jan 21 08:11:38 fambox kernel: [ 248.409534] sd 0:0:0:0: [sda] Synchronizing SCSI cache
Jan 21 08:11:38 fambox kernel: [ 248.409692] sd 0:0:0:0: [sda] Stopping disk
Jan 21 08:11:38 fambox kernel: [ 248.412157] sd 1:0:0:0: [sdb] Stopping disk
Jan 21 08:11:38 fambox kernel: [ 249.028442] PM: suspend of devices complete after 619.821 msecs
Jan 21 08:11:38 fambox kernel: [ 249.028587] PM: late suspend of devices complete after 0.143 msecs
Jan 21 08:11:38 fambox kernel: [ 249.044387] r8169 0000:02:00.0: System wakeup enabled by ACPI
Jan 21 08:11:38 fambox kernel: [ 249.124225] PM: noirq suspend of devices complete after 95.750 msecs
Jan 21 08:11:38 fambox kernel: [ 249.124491] ACPI: Preparing to enter system sleep state S3
Jan 21 08:11:38 fambox kernel: [ 249.148265] PM: Saving platform NVS memory
Jan 21 08:11:38 fambox kernel: [ 249.153095] Disabling non-boot CPUs ...
Jan 21 08:11:38 fambox kernel: [ 249.256055] smpboot: CPU 1 is now offline
Jan 21 08:11:38 fambox kernel: [ 249.359925] smpboot: CPU 2 is now offline
Jan 21 08:11:38 fambox kernel: [ 249.360418] Broke affinity for irq 23
Jan 21 08:11:38 fambox kernel: [ 249.463784] smpboot: CPU 3 is now offline
Jan 21 08:11:38 fambox kernel: [ 249.464123] Extended CMOS year: 2000
Jan 21 08:11:38 fambox kernel: [ 249.465361] ACPI: Low-level resume complete
Jan 21 08:11:38 fambox kernel: [ 249.465404] PM: Restoring platform NVS memory
Jan 21 08:11:38 fambox kernel: [ 249.466621] Extended CMOS year: 2000
Jan 21 08:11:38 fambox kernel: [ 249.466693] Enabling non-boot CPUs ...
Jan 21 08:11:38 fambox kernel: [ 249.466771] smpboot: Booting Node 0 Processor 1 APIC 0x1
Jan 21 08:11:38 fambox kernel: [ 249.477873] Disabled fast string operations
Jan 21 08:11:38 fambox kernel: [ 249.480182] CPU1 is up
Jan 21 08:11:38 fambox kernel: [ 249.480252] smpboot: Booting Node 0 Processor 2 APIC 0x2
Jan 21 08:11:38 fambox kernel: [ 249.491287] Disabled fast string operations
Jan 21 08:11:38 fambox kernel: [ 249.493605] CPU2 is up
Jan 21 08:11:38 fambox kernel: [ 249.493676] smpboot: Booting Node 0 Processor 3 APIC 0x3
Jan 21 08:11:38 fambox kernel: [ 249.504712] Disabled fast string operations
Jan 21 08:11:38 fambox kernel: [ 249.507110] CPU3 is up
Jan 21 08:11:38 fambox kernel: [ 249.511892] ACPI: Waking up from system sleep state S3
Jan 21 08:11:38 fambox kernel: [ 249.706123] PM: noirq resume of devices complete after 144.003 msecs
Jan 21 08:11:38 fambox kernel: [ 249.706274] PM: early resume of devices complete after 0.111 msecs
Jan 21 08:11:38 fambox kernel: [ 249.706310] i915 0000:00:02.0: setting latency timer to 64
Jan 21 08:11:38 fambox kernel: [ 249.706333] ehci-pci 0000:00:1a.0: setting latency timer to 64
Jan 21 08:11:38 fambox kernel: [ 249.706387] mei 0000:00:16.0: irq 47 for MSI/MSI-X
Jan 21 08:11:38 fambox kernel: [ 249.706429] ehci-pci 0000:00:1d.0: setting latency timer to 64
Jan 21 08:11:38 fambox kernel: [ 249.706447] snd_hda_intel 0000:00:1b.0: irq 50 for MSI/MSI-X
Jan 21 08:11:38 fambox kernel: [ 249.706508] r8169 0000:02:00.0: System wakeup disabled by ACPI
Jan 21 08:11:38 fambox kernel: [ 249.706622] usb usb3: root hub lost power or was reset
Jan 21 08:11:38 fambox kernel: [ 249.706624] usb usb4: root hub lost power or was reset
Jan 21 08:11:38 fambox kernel: [ 249.706626] iwlwifi 0000:01:00.0: RF_KILL bit toggled to enable radio.
Jan 21 08:11:38 fambox kernel: [ 249.706686] ahci 0000:00:1f.2: setting latency timer to 64
Jan 21 08:11:38 fambox kernel: [ 249.711344] xhci_hcd 0000:03:00.0: irq 41 for MSI/MSI-X
Jan 21 08:11:38 fambox kernel: [ 249.711352] xhci_hcd 0000:03:00.0: irq 42 for MSI/MSI-X
Jan 21 08:11:38 fambox kernel: [ 249.711360] xhci_hcd 0000:03:00.0: irq 43 for MSI/MSI-X
Jan 21 08:11:38 fambox kernel: [ 249.711369] xhci_hcd 0000:03:00.0: irq 44 for MSI/MSI-X
Jan 21 08:11:38 fambox kernel: [ 249.711376] xhci_hcd 0000:03:00.0: irq 45 for MSI/MSI-X
Jan 21 08:11:38 fambox kernel: [ 250.041632] ata2: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jan 21 08:11:38 fambox kernel: [ 250.045709] ata2.00: configured for UDMA/133
Jan 21 08:11:38 fambox kernel: [ 250.049618] ata4: SATA link down (SStatus 0 SControl 300)
Jan 21 08:11:38 fambox kernel: [ 250.057610] ata5: SATA link down (SStatus 0 SControl 300)
Jan 21 08:11:38 fambox kernel: [ 250.061687] sd 1:0:0:0: [sdb] Starting disk
Jan 21 08:11:38 fambox kernel: [ 250.117763] usb 1-1.2: reset low-speed USB device number 3 using ehci-pci
Jan 21 08:11:38 fambox kernel: [ 250.469164] usb 1-1.4: reset high-speed USB device number 4 using ehci-pci
Jan 21 08:11:38 fambox kernel: [ 251.528028] [drm] Enabling RC6 states: RC6 on, RC6p off, RC6pp off
Jan 21 08:11:38 fambox kernel: [ 252.079185] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Jan 21 08:11:38 fambox kernel: [ 252.081625] ata1.00: configured for UDMA/133
Jan 21 08:11:38 fambox kernel: [ 252.095265] sd 0:0:0:0: [sda] Starting disk
Jan 21 08:11:38 fambox kernel: [ 252.097227] Extended CMOS year: 2000
Jan 21 08:11:38 fambox kernel: [ 252.119773] PM: resume of devices complete after 2416.409 msecs
Jan 21 08:11:38 fambox kernel: [ 252.120213] PM: Finishing wakeup.
Jan 21 08:11:38 fambox kernel: [ 252.120216] Restarting tasks ... done.
Jan 21 08:11:38 fambox kernel: [ 252.128944] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:11:38 fambox kernel: [ 252.719180] iwlwifi 0000:01:00.0: L1 Enabled; Disabling L0S
Jan 21 08:11:38 fambox kernel: [ 252.726034] iwlwifi 0000:01:00.0: Radio type=0x1-0x2-0x0
Jan 21 08:11:39 fambox kernel: [ 252.955108] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Jan 21 08:11:45 fambox kernel: [ 259.272806] wlan0: authenticate with 00:04:0e:e4:00:3d
Jan 21 08:11:45 fambox kernel: [ 259.281463] wlan0: send auth to 00:04:0e:e4:00:3d (try 1/3)
Jan 21 08:11:45 fambox kernel: [ 259.283236] wlan0: authenticated
Jan 21 08:11:45 fambox kernel: [ 259.283530] iwlwifi 0000:01:00.0 wlan0: disabling HT as WMM/QoS is not supported by the AP
Jan 21 08:11:45 fambox kernel: [ 259.283541] iwlwifi 0000:01:00.0 wlan0: disabling VHT as WMM/QoS is not supported by the AP
Jan 21 08:11:45 fambox kernel: [ 259.286367] wlan0: associate with 00:04:0e:e4:00:3d (try 1/3)
Jan 21 08:11:45 fambox kernel: [ 259.290482] wlan0: RX AssocResp from 00:04:0e:e4:00:3d (capab=0x411 status=0 aid=1)
Jan 21 08:11:45 fambox kernel: [ 259.294170] wlan0: associated
Jan 21 08:11:45 fambox kernel: [ 259.294205] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Jan 21 08:12:33 fambox kernel: [ 307.235839] show_signal_msg: 36 callbacks suppressed
Jan 21 08:12:33 fambox kernel: [ 307.235844] firefox[3244]: segfault at 7fd133927428 ip 00007fd133908362 sp 00007fff8cfda778 error 7 in libGL.so.1.2.0[7fd133908000+7c000]
Jan 21 08:13:28 fambox kernel: [ 362.220464] PM: Syncing filesystems ... done.
Jan 21 08:13:28 fambox kernel: [ 362.385356] PM: Preparing system for mem sleep
Jan 21 08:13:37 fambox kernel: [ 366.625489] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:13:37 fambox kernel: [ 366.641644] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:13:37 fambox kernel: [ 366.657666] suspend debug: Waiting for 5 seconds.
Jan 21 08:13:37 fambox kernel: [ 371.614417] PM: Finishing wakeup.
Jan 21 08:13:37 fambox kernel: [ 371.614419] Restarting tasks ... done.
Jan 21 08:13:37 fambox kernel: [ 371.624384] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:13:39 fambox kernel: [ 372.627309] PM: Syncing filesystems ... done.
Jan 21 08:13:39 fambox kernel: [ 372.769925] PM: Preparing system for mem sleep
Jan 21 08:13:46 fambox kernel: [ 375.343360] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:13:46 fambox kernel: [ 375.359732] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:13:46 fambox kernel: [ 375.375833] suspend debug: Waiting for 5 seconds.
Jan 21 08:13:46 fambox kernel: [ 380.332539] PM: Finishing wakeup.
Jan 21 08:13:46 fambox kernel: [ 380.332540] Restarting tasks ... done.
Jan 21 08:13:46 fambox kernel: [ 380.345274] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:13:47 fambox kernel: [ 381.347598] PM: Syncing filesystems ... done.
Jan 21 08:13:47 fambox kernel: [ 381.612879] PM: Preparing system for mem sleep
Jan 21 08:13:56 fambox kernel: [ 384.777396] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:13:56 fambox kernel: [ 384.793742] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:13:56 fambox kernel: [ 384.809867] suspend debug: Waiting for 5 seconds.
Jan 21 08:13:56 fambox kernel: [ 389.766559] PM: Finishing wakeup.
Jan 21 08:13:56 fambox kernel: [ 389.766562] Restarting tasks ... done.
Jan 21 08:13:56 fambox kernel: [ 389.772358] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:13:57 fambox kernel: [ 390.775105] PM: Syncing filesystems ... done.
Jan 21 08:13:57 fambox kernel: [ 391.052390] PM: Preparing system for mem sleep
Jan 21 08:14:04 fambox kernel: [ 393.723525] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:14:04 fambox kernel: [ 393.740009] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:14:04 fambox kernel: [ 393.756006] suspend debug: Waiting for 5 seconds.
Jan 21 08:14:04 fambox kernel: [ 398.712691] PM: Finishing wakeup.
Jan 21 08:14:04 fambox kernel: [ 398.712693] Restarting tasks ... done.
Jan 21 08:14:04 fambox kernel: [ 398.720021] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:14:06 fambox kernel: [ 399.721844] PM: Syncing filesystems ... done.
Jan 21 08:14:06 fambox kernel: [ 400.115853] PM: Preparing system for mem sleep
Jan 21 08:14:12 fambox kernel: [ 401.760938] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:14:12 fambox kernel: [ 401.774315] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:14:12 fambox kernel: [ 401.790297] suspend debug: Waiting for 5 seconds.
Jan 21 08:14:12 fambox kernel: [ 406.746991] PM: Finishing wakeup.
Jan 21 08:14:12 fambox kernel: [ 406.746993] Restarting tasks ... done.
Jan 21 08:14:13 fambox kernel: [ 406.758469] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:14:14 fambox kernel: [ 407.763922] PM: Syncing filesystems ... done.
Jan 21 08:14:14 fambox kernel: [ 407.867994] PM: Preparing system for mem sleep
Jan 21 08:14:22 fambox kernel: [ 410.811958] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:14:22 fambox kernel: [ 410.828400] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:14:22 fambox kernel: [ 410.844408] suspend debug: Waiting for 5 seconds.
Jan 21 08:14:22 fambox kernel: [ 415.801093] PM: Finishing wakeup.
Jan 21 08:14:22 fambox kernel: [ 415.801095] Restarting tasks ... done.
Jan 21 08:14:22 fambox kernel: [ 415.808417] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:14:23 fambox kernel: [ 416.811223] PM: Syncing filesystems ... done.
Jan 21 08:14:23 fambox kernel: [ 416.909207] PM: Preparing system for mem sleep
Jan 21 08:14:30 fambox kernel: [ 418.902297] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:14:30 fambox kernel: [ 418.918607] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:14:30 fambox kernel: [ 418.934718] suspend debug: Waiting for 5 seconds.
Jan 21 08:14:30 fambox kernel: [ 423.891419] PM: Finishing wakeup.
Jan 21 08:14:30 fambox kernel: [ 423.891421] Restarting tasks ... done.
Jan 21 08:14:30 fambox kernel: [ 423.897050] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:14:31 fambox kernel: [ 424.902824] PM: Syncing filesystems ... done.
Jan 21 08:14:31 fambox kernel: [ 425.005597] PM: Preparing system for mem sleep
Jan 21 08:14:39 fambox kernel: [ 427.936413] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:14:39 fambox kernel: [ 427.952668] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:14:39 fambox kernel: [ 427.968820] suspend debug: Waiting for 5 seconds.
Jan 21 08:14:39 fambox kernel: [ 432.925545] PM: Finishing wakeup.
Jan 21 08:14:39 fambox kernel: [ 432.925547] Restarting tasks ... done.
Jan 21 08:14:39 fambox kernel: [ 432.933531] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:14:40 fambox kernel: [ 433.936467] PM: Syncing filesystems ... done.
Jan 21 08:14:40 fambox kernel: [ 434.309510] PM: Preparing system for mem sleep
Jan 21 08:14:48 fambox kernel: [ 436.806416] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:14:48 fambox kernel: [ 436.822973] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:14:48 fambox kernel: [ 436.838930] suspend debug: Waiting for 5 seconds.
Jan 21 08:14:48 fambox kernel: [ 441.795587] PM: Finishing wakeup.
Jan 21 08:14:48 fambox kernel: [ 441.795589] Restarting tasks ... done.
Jan 21 08:14:48 fambox kernel: [ 441.801976] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:14:49 fambox kernel: [ 442.804254] PM: Syncing filesystems ... done.
Jan 21 08:14:49 fambox kernel: [ 443.050353] PM: Preparing system for mem sleep
Jan 21 08:14:58 fambox kernel: [ 446.936427] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:14:58 fambox kernel: [ 446.952810] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:14:58 fambox kernel: [ 446.968839] suspend debug: Waiting for 5 seconds.
Jan 21 08:14:58 fambox kernel: [ 451.925556] PM: Finishing wakeup.
Jan 21 08:14:58 fambox kernel: [ 451.925558] Restarting tasks ... done.
Jan 21 08:14:58 fambox kernel: [ 451.930859] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:17:37 fambox kernel: [ 611.195107] SGI XFS with ACLs, security attributes, realtime, large block/inode numbers, no debug enabled
Jan 21 08:17:37 fambox kernel: [ 611.276930] Btrfs loaded
Jan 21 08:18:25 fambox kernel: [ 659.450269] PM: Syncing filesystems ... done.
Jan 21 08:18:25 fambox kernel: [ 659.560807] PM: Preparing system for mem sleep
Jan 21 08:18:52 fambox kernel: [ 666.004376] Freezing user space processes ...
Jan 21 08:18:52 fambox kernel: [ 686.014794] Freezing of tasks failed after 20.01 seconds (1 tasks refusing to freeze, wq_busy=0):
Jan 21 08:18:52 fambox kernel: [ 686.014926] cupsd D ffffffff8180d780 0 1044 1 0x00000004
Jan 21 08:18:52 fambox kernel: [ 686.014935] ffff880101a7be18 0000000000000046 ffff880101a7bdc8 0000000300000001
Jan 21 08:18:52 fambox kernel: [ 686.014944] ffff8801181b4560 ffff880101a7bfd8 ffff880101a7bfd8 ffff880101a7bfd8
Jan 21 08:18:52 fambox kernel: [ 686.014951] ffffffff81c15440 ffff8801181b4560 ffff880101a7be28 ffff88011857f800
Jan 21 08:18:52 fambox kernel: [ 686.014958] Call Trace:
Jan 21 08:18:52 fambox kernel: [ 686.014973] [<ffffffff816b7e39>] schedule+0x29/0x70
Jan 21 08:18:52 fambox kernel: [ 686.014985] [<ffffffff8128fdad>] jbd2_log_wait_commit+0xcd/0x1a0
Jan 21 08:18:52 fambox kernel: [ 686.014993] [<ffffffff8107eb90>] ? add_wait_queue+0x60/0x60
Jan 21 08:18:52 fambox kernel: [ 686.015001] [<ffffffff8122fed5>] ext4_sync_file+0x205/0x380
Jan 21 08:18:52 fambox kernel: [ 686.015009] [<ffffffff811c372d>] do_fsync+0x5d/0x90
Jan 21 08:18:52 fambox kernel: [ 686.015018] [<ffffffff81193792>] ? sys_write+0x52/0xa0
Jan 21 08:18:52 fambox kernel: [ 686.015024] [<ffffffff811c3b10>] sys_fsync+0x10/0x20
Jan 21 08:18:52 fambox kernel: [ 686.015031] [<ffffffff816c189d>] system_call_fastpath+0x1a/0x1f
Jan 21 08:18:52 fambox kernel: [ 686.015093]
Jan 21 08:18:52 fambox kernel: [ 686.015096] Restarting tasks ... done.
Jan 21 08:18:52 fambox kernel: [ 686.024031] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:18:52 fambox kernel: [ 686.024594] PM: Syncing filesystems ... done.
Jan 21 08:18:52 fambox kernel: [ 686.528387] PM: Preparing system for mem sleep
Jan 21 08:19:00 fambox kernel: [ 689.389593] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:19:00 fambox kernel: [ 689.406076] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:19:00 fambox kernel: [ 689.422109] suspend debug: Waiting for 5 seconds.
Jan 21 08:19:00 fambox kernel: [ 694.378815] PM: Finishing wakeup.
Jan 21 08:19:00 fambox kernel: [ 694.378817] Restarting tasks ... done.
Jan 21 08:19:00 fambox kernel: [ 694.386261] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:19:01 fambox kernel: [ 695.388216] PM: Syncing filesystems ... done.
Jan 21 08:19:01 fambox kernel: [ 695.669009] PM: Preparing system for mem sleep
Jan 21 08:19:09 fambox kernel: [ 698.663894] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:19:09 fambox kernel: [ 698.680202] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:19:09 fambox kernel: [ 698.696290] suspend debug: Waiting for 5 seconds.
Jan 21 08:19:09 fambox kernel: [ 703.652954] PM: Finishing wakeup.
Jan 21 08:19:09 fambox kernel: [ 703.652956] Restarting tasks ... done.
Jan 21 08:19:09 fambox kernel: [ 703.657023] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:19:11 fambox kernel: [ 704.658252] PM: Syncing filesystems ... done.
Jan 21 08:19:11 fambox kernel: [ 704.773724] PM: Preparing system for mem sleep
Jan 21 08:19:36 fambox kernel: [ 709.879880] Freezing user space processes ... (elapsed 0.06 seconds) done.
Jan 21 08:19:36 fambox kernel: [ 709.944282] Freezing remaining freezable tasks ...
Jan 21 08:19:36 fambox kernel: [ 729.946099] Freezing of tasks failed after 20.01 seconds (1 tasks refusing to freeze, wq_busy=0):
Jan 21 08:19:36 fambox kernel: [ 729.946222] jbd2/loop0-8 D ffffffff8180d780 0 311 2 0x00000000
Jan 21 08:19:36 fambox kernel: [ 729.946231] ffff880115353b68 0000000000000046 ffff8801180f1720 0000000000000001
Jan 21 08:19:36 fambox kernel: [ 729.946240] ffff8801180f1720 ffff880115353fd8 ffff880115353fd8 ffff880115353fd8
Jan 21 08:19:36 fambox kernel: [ 729.946246] ffff880119b32e40 ffff8801180f1720 ffff880115353b68 ffff88011fa94738
Jan 21 08:19:36 fambox kernel: [ 729.946253] Call Trace:
Jan 21 08:19:36 fambox kernel: [ 729.946271] [<ffffffff811c5bb0>] ? __wait_on_buffer+0x30/0x30
Jan 21 08:19:36 fambox kernel: [ 729.946279] [<ffffffff816b7e39>] schedule+0x29/0x70
Jan 21 08:19:36 fambox kernel: [ 729.946285] [<ffffffff816b7f0f>] io_schedule+0x8f/0xd0
Jan 21 08:19:36 fambox kernel: [ 729.946292] [<ffffffff811c5bbe>] sleep_on_buffer+0xe/0x20
Jan 21 08:19:36 fambox kernel: [ 729.946301] [<ffffffff816b670f>] __wait_on_bit+0x5f/0x90
Jan 21 08:19:36 fambox kernel: [ 729.946308] [<ffffffff811c5271>] ? submit_bh+0x121/0x1e0
Jan 21 08:19:36 fambox kernel: [ 729.946315] [<ffffffff811c5bb0>] ? __wait_on_buffer+0x30/0x30
Jan 21 08:19:36 fambox kernel: [ 729.946323] [<ffffffff816b67bc>] out_of_line_wait_on_bit+0x7c/0x90
Jan 21 08:19:36 fambox kernel: [ 729.946331] [<ffffffff8107ebd0>] ? autoremove_wake_function+0x40/0x40
Jan 21 08:19:36 fambox kernel: [ 729.946338] [<ffffffff811c5bae>] __wait_on_buffer+0x2e/0x30
Jan 21 08:19:36 fambox kernel: [ 729.946347] [<ffffffff8128b75c>] jbd2_journal_commit_transaction+0x18cc/0x1d60
Jan 21 08:19:36 fambox kernel: [ 729.946355] [<ffffffff81093d78>] ? set_next_entity+0xa8/0xc0
Jan 21 08:19:36 fambox kernel: [ 729.946362] [<ffffffff816b8fce>] ? _raw_spin_lock_irqsave+0x2e/0x40
Jan 21 08:19:36 fambox kernel: [ 729.946370] [<ffffffff81069fcf>] ? try_to_del_timer_sync+0x4f/0x70
Jan 21 08:19:36 fambox kernel: [ 729.946380] [<ffffffff8128ff66>] kjournald2+0xd6/0x3e0
Jan 21 08:19:36 fambox kernel: [ 729.946386] [<ffffffff8107eb90>] ? add_wait_queue+0x60/0x60
Jan 21 08:19:36 fambox kernel: [ 729.946394] [<ffffffff8128fe90>] ? commit_timeout+0x10/0x10
Jan 21 08:19:36 fambox kernel: [ 729.946399] [<ffffffff8107dfa0>] kthread+0xc0/0xd0
Jan 21 08:19:36 fambox kernel: [ 729.946405] [<ffffffff8107dee0>] ? flush_kthread_worker+0xb0/0xb0
Jan 21 08:19:36 fambox kernel: [ 729.946412] [<ffffffff816c17ec>] ret_from_fork+0x7c/0xb0
Jan 21 08:19:36 fambox kernel: [ 729.946418] [<ffffffff8107dee0>] ? flush_kthread_worker+0xb0/0xb0
Jan 21 08:19:36 fambox kernel: [ 729.946481]
Jan 21 08:19:36 fambox kernel: [ 729.946484] Restarting kernel threads ... done.
Jan 21 08:19:36 fambox kernel: [ 729.946638] Restarting tasks ... done.
Jan 21 08:19:36 fambox kernel: [ 729.957292] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:19:36 fambox kernel: [ 729.957655] PM: Syncing filesystems ... done.
Jan 21 08:19:36 fambox kernel: [ 730.090702] PM: Preparing system for mem sleep
Jan 21 08:19:46 fambox kernel: [ 735.049968] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:19:46 fambox kernel: [ 735.066344] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:19:46 fambox kernel: [ 735.082470] suspend debug: Waiting for 5 seconds.
Jan 21 08:19:46 fambox kernel: [ 740.039150] PM: Finishing wakeup.
Jan 21 08:19:46 fambox kernel: [ 740.039152] Restarting tasks ... done.
Jan 21 08:19:46 fambox kernel: [ 740.044754] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:19:47 fambox kernel: [ 741.047618] PM: Syncing filesystems ... done.
Jan 21 08:19:47 fambox kernel: [ 741.144638] PM: Preparing system for mem sleep
Jan 21 08:20:12 fambox kernel: [ 746.474101] Freezing user space processes ... (elapsed 0.04 seconds) done.
Jan 21 08:20:12 fambox kernel: [ 746.522356] Freezing remaining freezable tasks ...
Jan 21 08:20:12 fambox kernel: [ 766.524155] Freezing of tasks failed after 20.01 seconds (1 tasks refusing to freeze, wq_busy=0):
Jan 21 08:20:12 fambox kernel: [ 766.524280] jbd2/loop0-8 D ffffffff8180d780 0 311 2 0x00000000
Jan 21 08:20:12 fambox kernel: [ 766.524289] ffff880115353b68 0000000000000046 ffff880115353b08 ffffffff81044c29
Jan 21 08:20:12 fambox kernel: [ 766.524297] ffff8801180f1720 ffff880115353fd8 ffff880115353fd8 ffff880115353fd8
Jan 21 08:20:12 fambox kernel: [ 766.524304] ffff880119b32e40 ffff8801180f1720 ffff880115353b68 ffff88011fa94738
Jan 21 08:20:12 fambox kernel: [ 766.524311] Call Trace:
Jan 21 08:20:12 fambox kernel: [ 766.524330] [<ffffffff81044c29>] ? default_spin_lock_flags+0x9/0x10
Jan 21 08:20:12 fambox kernel: [ 766.524340] [<ffffffff811c5bb0>] ? __wait_on_buffer+0x30/0x30
Jan 21 08:20:12 fambox kernel: [ 766.524349] [<ffffffff816b7e39>] schedule+0x29/0x70
Jan 21 08:20:12 fambox kernel: [ 766.524355] [<ffffffff816b7f0f>] io_schedule+0x8f/0xd0
Jan 21 08:20:12 fambox kernel: [ 766.524361] [<ffffffff811c5bbe>] sleep_on_buffer+0xe/0x20
Jan 21 08:20:12 fambox kernel: [ 766.524371] [<ffffffff816b670f>] __wait_on_bit+0x5f/0x90
Jan 21 08:20:12 fambox kernel: [ 766.524378] [<ffffffff811c5271>] ? submit_bh+0x121/0x1e0
Jan 21 08:20:12 fambox kernel: [ 766.524384] [<ffffffff811c5bb0>] ? __wait_on_buffer+0x30/0x30
Jan 21 08:20:12 fambox kernel: [ 766.524392] [<ffffffff816b67bc>] out_of_line_wait_on_bit+0x7c/0x90
Jan 21 08:20:12 fambox kernel: [ 766.524400] [<ffffffff8107ebd0>] ? autoremove_wake_function+0x40/0x40
Jan 21 08:20:12 fambox kernel: [ 766.524407] [<ffffffff811c5bae>] __wait_on_buffer+0x2e/0x30
Jan 21 08:20:12 fambox kernel: [ 766.524417] [<ffffffff8128b75c>] jbd2_journal_commit_transaction+0x18cc/0x1d60
Jan 21 08:20:12 fambox kernel: [ 766.524425] [<ffffffff816b8fce>] ? _raw_spin_lock_irqsave+0x2e/0x40
Jan 21 08:20:12 fambox kernel: [ 766.524434] [<ffffffff81069fcf>] ? try_to_del_timer_sync+0x4f/0x70
Jan 21 08:20:12 fambox kernel: [ 766.524444] [<ffffffff8128ff66>] kjournald2+0xd6/0x3e0
Jan 21 08:20:12 fambox kernel: [ 766.524450] [<ffffffff8107eb90>] ? add_wait_queue+0x60/0x60
Jan 21 08:20:12 fambox kernel: [ 766.524458] [<ffffffff8128fe90>] ? commit_timeout+0x10/0x10
Jan 21 08:20:12 fambox kernel: [ 766.524463] [<ffffffff8107dfa0>] kthread+0xc0/0xd0
Jan 21 08:20:12 fambox kernel: [ 766.524469] [<ffffffff8107dee0>] ? flush_kthread_worker+0xb0/0xb0
Jan 21 08:20:12 fambox kernel: [ 766.524477] [<ffffffff816c17ec>] ret_from_fork+0x7c/0xb0
Jan 21 08:20:12 fambox kernel: [ 766.524482] [<ffffffff8107dee0>] ? flush_kthread_worker+0xb0/0xb0
Jan 21 08:20:12 fambox kernel: [ 766.524549]
Jan 21 08:20:12 fambox kernel: [ 766.524552] Restarting kernel threads ... done.
Jan 21 08:20:12 fambox kernel: [ 766.524709] Restarting tasks ... done.
Jan 21 08:20:12 fambox kernel: [ 766.536532] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:20:13 fambox kernel: [ 766.537083] PM: Syncing filesystems ... done.
Jan 21 08:20:13 fambox kernel: [ 766.787883] PM: Preparing system for mem sleep
Jan 21 08:20:19 fambox kernel: [ 768.478192] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:20:19 fambox kernel: [ 768.494712] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:20:19 fambox kernel: [ 768.510734] suspend debug: Waiting for 5 seconds.
Jan 21 08:20:19 fambox kernel: [ 773.467417] PM: Finishing wakeup.
Jan 21 08:20:19 fambox kernel: [ 773.467420] Restarting tasks ... done.
Jan 21 08:20:19 fambox kernel: [ 773.472865] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:20:20 fambox kernel: [ 774.477386] PM: Syncing filesystems ... done.
Jan 21 08:20:20 fambox kernel: [ 774.593585] PM: Preparing system for mem sleep
Jan 21 08:20:30 fambox kernel: [ 778.647805] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:20:30 fambox kernel: [ 778.663513] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:20:30 fambox kernel: [ 778.679553] suspend debug: Waiting for 5 seconds.
Jan 21 08:20:30 fambox kernel: [ 783.636254] PM: Finishing wakeup.
Jan 21 08:20:30 fambox kernel: [ 783.636256] Restarting tasks ... done.
Jan 21 08:20:30 fambox kernel: [ 783.641310] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:20:31 fambox kernel: [ 784.643646] PM: Syncing filesystems ... done.
Jan 21 08:20:31 fambox kernel: [ 784.917006] PM: Preparing system for mem sleep
Jan 21 08:20:41 fambox kernel: [ 790.494656] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:20:41 fambox kernel: [ 790.511009] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:20:41 fambox kernel: [ 790.527184] suspend debug: Waiting for 5 seconds.
Jan 21 08:20:41 fambox kernel: [ 795.483884] PM: Finishing wakeup.
Jan 21 08:20:41 fambox kernel: [ 795.483885] Restarting tasks ... done.
Jan 21 08:20:41 fambox kernel: [ 795.490986] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:20:43 fambox kernel: [ 796.494290] PM: Syncing filesystems ... done.
Jan 21 08:20:43 fambox kernel: [ 796.622749] PM: Preparing system for mem sleep
Jan 21 08:20:54 fambox kernel: [ 802.917838] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jan 21 08:20:54 fambox kernel: [ 802.934348] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 21 08:20:54 fambox kernel: [ 802.950288] suspend debug: Waiting for 5 seconds.
Jan 21 08:20:54 fambox kernel: [ 807.907038] PM: Finishing wakeup.
Jan 21 08:20:54 fambox kernel: [ 807.907040] Restarting tasks ... done.
Jan 21 08:20:54 fambox kernel: [ 807.915538] video LNXVIDEO:00: Restoring backlight state
Jan 21 08:22:18 fambox kernel: [ 892.419318] type=1400 audit(1358752938.864:24): apparmor="DENIED" operation="capable" parent=1 profile="/usr/sbin/cupsd" pid=1044 comm="cupsd" pid=1044 comm="cupsd" capability=36 capname="block_suspend"
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-21 10:47 ` Jan Kara
2013-01-21 11:40 ` Sedat Dilek
@ 2013-01-21 12:02 ` Carlos Maiolino
1 sibling, 0 replies; 26+ messages in thread
From: Carlos Maiolino @ 2013-01-21 12:02 UTC (permalink / raw)
To: Jan Kara
Cc: Sedat Dilek, Eric Sandeen, linux-fsdevel, Ext4 Developers List,
Theodore Ts'o, LKML, linux-next
On Mon, Jan 21, 2013 at 11:47:33AM +0100, Jan Kara wrote:
> On Sun 20-01-13 01:06:40, Sedat Dilek wrote:
> > On Sun, Jan 20, 2013 at 12:44 AM, Sedat Dilek <sedat.dilek@gmail.com> wrote:
> > > Hi,
> > >
> > > I and some others hit a similiar problem in Linux-Next
> > > (next-20130118), please see [1] and [2].
> > >
> > > [3] has a interim analyze of my problems.
> > >
> > > After suspecting the problem was caused by TTY-NEXT, it turned out to
> > > be a JBD2 problem finally.
> > > The freezer/pm_test was helpful to hit the issue (Thanks Rafael for the hint!).
> > >
> > > So, the issue has two faces: TTY and JBD2.
> > > [4] gives a list and URLs of the patches I had to apply to have a
> > > clean system again.
> > >
> > > After applying the two TTY patches (without Eric's JBD2-fix!) the
> > > call-trace after freezer/pm_test looked like this;
> > >
> > > [ 433.527986] PM: Syncing filesystems ... done.
> > > [ 433.843761] PM: Preparing system for mem sleep
> > > [ 436.306002] Freezing user space processes ...
> > > [ 456.304956] Freezing of tasks failed after 20.01 seconds (1 tasks
> > > refusing to freeze, wq_busy=0):
> > > [ 456.305060] Cache I/O D ffffffff8180d780 0 2132 1 0x00000004
> > > [ 456.305065] ffff88007b9dfe18 0000000000000046 ffff88007b9dfdc8
> > > 0000000300000001
> > > [ 456.305069] ffff880097e21720 ffff88007b9dffd8 ffff88007b9dffd8
> > > ffff88007b9dffd8
> > > [ 456.305072] ffff880119b32e40 ffff880097e21720 ffff88007b9dfe28
> > > ffff880118077800
> > > [ 456.305076] Call Trace:
> > > [ 456.305085] [<ffffffff816b7469>] schedule+0x29/0x70
> > > [ 456.305089] [<ffffffff8129067d>] jbd2_log_wait_commit+0xcd/0x1a0
> > > [ 456.305094] [<ffffffff8107eac0>] ? add_wait_queue+0x60/0x60
> > > [ 456.305098] [<ffffffff812307a5>] ext4_sync_file+0x205/0x380
> > > [ 456.305103] [<ffffffff811c43ad>] do_fsync+0x5d/0x90
> > > [ 456.305108] [<ffffffff8119442b>] ? sys_write+0x6b/0xa0
> > > [ 456.305111] [<ffffffff811c4790>] sys_fsync+0x10/0x20
> > > [ 456.305114] [<ffffffff816c0edd>] system_call_fastpath+0x1a/0x1f
> > > [ 456.305122]
> > > [ 456.305124] Restarting tasks ... done.
> > > [ 456.315056] video LNXVIDEO:00: Restoring backlight state
> > >
> > > After applying Eric's patch [5], I could not hit the call-trace again.
> > > NOTE: The patch is from December 2012 and is not shipped in latest Linux-Next.
> > >
> > > The attached testcase script was helpful to force the call-trace.
> > > I have run 50 loops of it w/o an issue!
> > >
> > > Feel free to add a Reported-by/Tested-by.
> > > ( The issue kept me busy for the last days. )
> > >
> > > Regards,
> > > - Sedat -
> > >
> > > [1] http://marc.info/?t=135283664600002&r=1&w=2
> > > [2] http://marc.info/?t=135862023700004&r=1&w=2
> > > [3] http://marc.info/?l=linux-kernel&m=135862010419101&w=2
> > > [4] http://marc.info/?l=linux-next&m=135863550923093&w=2
> > > [5] http://patchwork.ozlabs.org/patch/207237/
> >
> > Hi all,
> >
> > this is really ugly... I could cry!
> >
> > GRRR, I have hit the original issue again while running my testcase script!
> >
> > [ 363.831226] PM: Syncing filesystems ... done.
> > [ 363.988855] PM: Preparing system for mem sleep
> > [ 369.032965] Freezing user space processes ... (elapsed 0.11 seconds) done.
> > [ 369.145792] Freezing remaining freezable tasks ...
> > [ 389.137643] Freezing of tasks failed after 20.01 seconds (1 tasks
> > refusing to freeze, wq_busy=0):
> > [ 389.137760] jbd2/loop0-8 D ffffffff8180d780 0 295 2 0x00000000
> > [ 389.137769] ffff8801181dfb68 0000000000000046 ffff880117de5c80
> > 0000000000000001
> > [ 389.137778] ffff880117de5c80 ffff8801181dffd8 ffff8801181dffd8
> > ffff8801181dffd8
> > [ 389.137784] ffffffff81c15440 ffff880117de5c80 ffff8801181dfb68
> > ffff88011fa14738
> > [ 389.137791] Call Trace:
> > [ 389.137810] [<ffffffff811c6830>] ? __wait_on_buffer+0x30/0x30
> > [ 389.137819] [<ffffffff816b7479>] schedule+0x29/0x70
> > [ 389.137825] [<ffffffff816b754f>] io_schedule+0x8f/0xd0
> > [ 389.137832] [<ffffffff811c683e>] sleep_on_buffer+0xe/0x20
> > [ 389.137842] [<ffffffff816b5d4f>] __wait_on_bit+0x5f/0x90
> > [ 389.137849] [<ffffffff811c5ef1>] ? submit_bh+0x121/0x1e0
> > [ 389.137856] [<ffffffff811c6830>] ? __wait_on_buffer+0x30/0x30
> > [ 389.137864] [<ffffffff816b5dfc>] out_of_line_wait_on_bit+0x7c/0x90
> > [ 389.137873] [<ffffffff8107eb00>] ? autoremove_wake_function+0x40/0x40
> > [ 389.137879] [<ffffffff811c682e>] __wait_on_buffer+0x2e/0x30
> > [ 389.137891] [<ffffffff8128c02c>]
> > jbd2_journal_commit_transaction+0x18cc/0x1d60
> > [ 389.137899] [<ffffffff816b860e>] ? _raw_spin_lock_irqsave+0x2e/0x40
> > [ 389.137908] [<ffffffff81069fbf>] ? try_to_del_timer_sync+0x4f/0x70
> > [ 389.137915] [<ffffffff81290836>] kjournald2+0xd6/0x3e0
> > [ 389.137921] [<ffffffff8107eac0>] ? add_wait_queue+0x60/0x60
> > [ 389.137926] [<ffffffff81290760>] ? commit_timeout+0x10/0x10
> > [ 389.137932] [<ffffffff8107ded0>] kthread+0xc0/0xd0
> > [ 389.137939] [<ffffffff8107de10>] ? flush_kthread_worker+0xb0/0xb0
> > [ 389.137946] [<ffffffff816c0e2c>] ret_from_fork+0x7c/0xb0
> > [ 389.137951] [<ffffffff8107de10>] ? flush_kthread_worker+0xb0/0xb0
> > [ 389.138017]
> > [ 389.138021] Restarting kernel threads ... done.
> > [ 389.138173] Restarting tasks ... done.
> > [ 389.147980] video LNXVIDEO:00: Restoring backlight state
> >
> > I suspect there are still issues in JBD2 (BTW I run here EXT4FS).
> >
> > [ 389.137643] Freezing of tasks failed after 20.01 seconds (1 tasks
> > refusing to freeze, wq_busy=0):
> > [ 389.137760] jbd2/loop0-8 D ffffffff8180d780 0 295 2 0x00000000
> >
> > Have a good night, /me -> watching TV!
> The traces don't suggest an ext4/jbd2 problem. What is happening is that
> jbd2 is waiting for IO to finish and that never happens. Seeing that you
> loop device I'd think it's some interaction of the loop device and
> freezing. Can you reproduce the issue without the loop device (i.e. with
> the filesystem directly on e.g. scsi disk)? I suspect the reason is
> something like that the backing filesystem is already frozen so filesystem
> on top of it cannot write all the data and hangs waiting for IO -> suspend
> doesn't happen. Contents of /proc/mounts and losetup -l would help us
> understand what's going on.
^^^ Shouldn't be `losetup -a`?
>
> Honza
> --
> Jan Kara <jack@suse.cz>
> SUSE Labs, CR
> --
> To unsubscribe from this list: send the line "unsubscribe linux-fsdevel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
--
Carlos
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-21 11:40 ` Sedat Dilek
@ 2013-01-21 12:30 ` Sedat Dilek
2013-01-21 14:07 ` Jan Kara
0 siblings, 1 reply; 26+ messages in thread
From: Sedat Dilek @ 2013-01-21 12:30 UTC (permalink / raw)
To: Jan Kara
Cc: Eric Sandeen, linux-fsdevel, Ext4 Developers List,
Theodore Ts'o, LKML, linux-next
On Mon, Jan 21, 2013 at 12:40 PM, Sedat Dilek <sedat.dilek@gmail.com> wrote:
> On Mon, Jan 21, 2013 at 11:47 AM, Jan Kara <jack@suse.cz> wrote:
>> On Sun 20-01-13 01:06:40, Sedat Dilek wrote:
>>> On Sun, Jan 20, 2013 at 12:44 AM, Sedat Dilek <sedat.dilek@gmail.com> wrote:
>>> > Hi,
>>> >
>>> > I and some others hit a similiar problem in Linux-Next
>>> > (next-20130118), please see [1] and [2].
>>> >
>>> > [3] has a interim analyze of my problems.
>>> >
>>> > After suspecting the problem was caused by TTY-NEXT, it turned out to
>>> > be a JBD2 problem finally.
>>> > The freezer/pm_test was helpful to hit the issue (Thanks Rafael for the hint!).
>>> >
>>> > So, the issue has two faces: TTY and JBD2.
>>> > [4] gives a list and URLs of the patches I had to apply to have a
>>> > clean system again.
>>> >
>>> > After applying the two TTY patches (without Eric's JBD2-fix!) the
>>> > call-trace after freezer/pm_test looked like this;
>>> >
>>> > [ 433.527986] PM: Syncing filesystems ... done.
>>> > [ 433.843761] PM: Preparing system for mem sleep
>>> > [ 436.306002] Freezing user space processes ...
>>> > [ 456.304956] Freezing of tasks failed after 20.01 seconds (1 tasks
>>> > refusing to freeze, wq_busy=0):
>>> > [ 456.305060] Cache I/O D ffffffff8180d780 0 2132 1 0x00000004
>>> > [ 456.305065] ffff88007b9dfe18 0000000000000046 ffff88007b9dfdc8
>>> > 0000000300000001
>>> > [ 456.305069] ffff880097e21720 ffff88007b9dffd8 ffff88007b9dffd8
>>> > ffff88007b9dffd8
>>> > [ 456.305072] ffff880119b32e40 ffff880097e21720 ffff88007b9dfe28
>>> > ffff880118077800
>>> > [ 456.305076] Call Trace:
>>> > [ 456.305085] [<ffffffff816b7469>] schedule+0x29/0x70
>>> > [ 456.305089] [<ffffffff8129067d>] jbd2_log_wait_commit+0xcd/0x1a0
>>> > [ 456.305094] [<ffffffff8107eac0>] ? add_wait_queue+0x60/0x60
>>> > [ 456.305098] [<ffffffff812307a5>] ext4_sync_file+0x205/0x380
>>> > [ 456.305103] [<ffffffff811c43ad>] do_fsync+0x5d/0x90
>>> > [ 456.305108] [<ffffffff8119442b>] ? sys_write+0x6b/0xa0
>>> > [ 456.305111] [<ffffffff811c4790>] sys_fsync+0x10/0x20
>>> > [ 456.305114] [<ffffffff816c0edd>] system_call_fastpath+0x1a/0x1f
>>> > [ 456.305122]
>>> > [ 456.305124] Restarting tasks ... done.
>>> > [ 456.315056] video LNXVIDEO:00: Restoring backlight state
>>> >
>>> > After applying Eric's patch [5], I could not hit the call-trace again.
>>> > NOTE: The patch is from December 2012 and is not shipped in latest Linux-Next.
>>> >
>>> > The attached testcase script was helpful to force the call-trace.
>>> > I have run 50 loops of it w/o an issue!
>>> >
>>> > Feel free to add a Reported-by/Tested-by.
>>> > ( The issue kept me busy for the last days. )
>>> >
>>> > Regards,
>>> > - Sedat -
>>> >
>>> > [1] http://marc.info/?t=135283664600002&r=1&w=2
>>> > [2] http://marc.info/?t=135862023700004&r=1&w=2
>>> > [3] http://marc.info/?l=linux-kernel&m=135862010419101&w=2
>>> > [4] http://marc.info/?l=linux-next&m=135863550923093&w=2
>>> > [5] http://patchwork.ozlabs.org/patch/207237/
>>>
>>> Hi all,
>>>
>>> this is really ugly... I could cry!
>>>
>>> GRRR, I have hit the original issue again while running my testcase script!
>>>
>>> [ 363.831226] PM: Syncing filesystems ... done.
>>> [ 363.988855] PM: Preparing system for mem sleep
>>> [ 369.032965] Freezing user space processes ... (elapsed 0.11 seconds) done.
>>> [ 369.145792] Freezing remaining freezable tasks ...
>>> [ 389.137643] Freezing of tasks failed after 20.01 seconds (1 tasks
>>> refusing to freeze, wq_busy=0):
>>> [ 389.137760] jbd2/loop0-8 D ffffffff8180d780 0 295 2 0x00000000
>>> [ 389.137769] ffff8801181dfb68 0000000000000046 ffff880117de5c80
>>> 0000000000000001
>>> [ 389.137778] ffff880117de5c80 ffff8801181dffd8 ffff8801181dffd8
>>> ffff8801181dffd8
>>> [ 389.137784] ffffffff81c15440 ffff880117de5c80 ffff8801181dfb68
>>> ffff88011fa14738
>>> [ 389.137791] Call Trace:
>>> [ 389.137810] [<ffffffff811c6830>] ? __wait_on_buffer+0x30/0x30
>>> [ 389.137819] [<ffffffff816b7479>] schedule+0x29/0x70
>>> [ 389.137825] [<ffffffff816b754f>] io_schedule+0x8f/0xd0
>>> [ 389.137832] [<ffffffff811c683e>] sleep_on_buffer+0xe/0x20
>>> [ 389.137842] [<ffffffff816b5d4f>] __wait_on_bit+0x5f/0x90
>>> [ 389.137849] [<ffffffff811c5ef1>] ? submit_bh+0x121/0x1e0
>>> [ 389.137856] [<ffffffff811c6830>] ? __wait_on_buffer+0x30/0x30
>>> [ 389.137864] [<ffffffff816b5dfc>] out_of_line_wait_on_bit+0x7c/0x90
>>> [ 389.137873] [<ffffffff8107eb00>] ? autoremove_wake_function+0x40/0x40
>>> [ 389.137879] [<ffffffff811c682e>] __wait_on_buffer+0x2e/0x30
>>> [ 389.137891] [<ffffffff8128c02c>]
>>> jbd2_journal_commit_transaction+0x18cc/0x1d60
>>> [ 389.137899] [<ffffffff816b860e>] ? _raw_spin_lock_irqsave+0x2e/0x40
>>> [ 389.137908] [<ffffffff81069fbf>] ? try_to_del_timer_sync+0x4f/0x70
>>> [ 389.137915] [<ffffffff81290836>] kjournald2+0xd6/0x3e0
>>> [ 389.137921] [<ffffffff8107eac0>] ? add_wait_queue+0x60/0x60
>>> [ 389.137926] [<ffffffff81290760>] ? commit_timeout+0x10/0x10
>>> [ 389.137932] [<ffffffff8107ded0>] kthread+0xc0/0xd0
>>> [ 389.137939] [<ffffffff8107de10>] ? flush_kthread_worker+0xb0/0xb0
>>> [ 389.137946] [<ffffffff816c0e2c>] ret_from_fork+0x7c/0xb0
>>> [ 389.137951] [<ffffffff8107de10>] ? flush_kthread_worker+0xb0/0xb0
>>> [ 389.138017]
>>> [ 389.138021] Restarting kernel threads ... done.
>>> [ 389.138173] Restarting tasks ... done.
>>> [ 389.147980] video LNXVIDEO:00: Restoring backlight state
>>>
>>> I suspect there are still issues in JBD2 (BTW I run here EXT4FS).
>>>
>>> [ 389.137643] Freezing of tasks failed after 20.01 seconds (1 tasks
>>> refusing to freeze, wq_busy=0):
>>> [ 389.137760] jbd2/loop0-8 D ffffffff8180d780 0 295 2 0x00000000
>>>
>>> Have a good night, /me -> watching TV!
>> The traces don't suggest an ext4/jbd2 problem. What is happening is that
>> jbd2 is waiting for IO to finish and that never happens. Seeing that you
>> loop device I'd think it's some interaction of the loop device and
>> freezing. Can you reproduce the issue without the loop device (i.e. with
>> the filesystem directly on e.g. scsi disk)? I suspect the reason is
>> something like that the backing filesystem is already frozen so filesystem
>> on top of it cannot write all the data and hangs waiting for IO -> suspend
>> doesn't happen. Contents of /proc/mounts and losetup -l would help us
>> understand what's going on.
>>
>
> As said I am here in a very uncommon WUBI environment means my
> Ubuntu/precise rootfs-image lays on the Win7-partition (NTFS).
> Your explanation sounds reasonable to me as this line from my attached
> testcase causes the troubles.
>
> echo mem > /sys/power/state && sleep 1
>
> So, /sys/ is not writable immediately after freezer ends
>
> I checked again and again my logs and have seen "starving" lines
> reported by rtkit-daemon, but did not really get wiser what they want
> to tell me. Stopping rtkit-daemon or resetting all or all-known
> threads before running my pm_test/freezer did not help, too.
>
> /usr/sbin/rtkitctl --help
> rtkitctl [options]
>
> -h, --help Show this help
> --version Show version
>
> --reset-known Reset real-time status of known threads
> --reset-all Reset real-time status of all threads
> --start Start RealtimeKit if it is not running already
> -k, --exit Terminate running RealtimeKit daemon
>
> Here are the outputs you wanted with some more (fstab, grub-config) etc.
> I have here no -l option for losetup command.
>
>
> - Sedat -
>
> P.S.: Outputs for Honza...
>
> $ sudo cat /proc/mounts
> rootfs / rootfs rw 0 0
> sysfs /sys sysfs rw,nosuid,nodev,noexec,relatime 0 0
> proc /proc proc rw,nosuid,nodev,noexec,relatime 0 0
> udev /dev devtmpfs rw,relatime,size=1966948k,nr_inodes=491737,mode=755 0 0
> devpts /dev/pts devpts rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000 0 0
> tmpfs /run tmpfs rw,nosuid,relatime,size=788076k,mode=755 0 0
> /dev/sda2 /host fuseblk
> rw,nosuid,nodev,relatime,user_id=0,group_id=0,allow_other,blksize=4096
> 0 0
> /dev/loop0 / ext4 rw,relatime,errors=remount-ro,data=ordered 0 0
> none /sys/fs/fuse/connections fusectl rw,relatime 0 0
> none /sys/kernel/debug debugfs rw,relatime 0 0
> none /sys/kernel/security securityfs rw,relatime 0 0
> none /run/lock tmpfs rw,nosuid,nodev,noexec,relatime,size=5120k 0 0
> none /run/shm tmpfs rw,nosuid,nodev,relatime 0 0
> gvfs-fuse-daemon /home/wearefam/.gvfs fuse.gvfs-fuse-daemon
> rw,nosuid,nodev,relatime,user_id=1000,group_id=1000 0 0
>
> $ sudo losetup --all --verbose
> /dev/loop0: [0802]:17982 (/host/ubuntu/disks/root.disk)
>
> $ sudo losetup --find --verbose
> Loop device is /dev/loop1
> /dev/loop1
>
> [ /etc/fstab ]
> # /etc/fstab: static file system information.
>
> # Use 'blkid' to print the universally unique identifier for a
> # device; this may be used with UUID= as a more robust way to name devices
> # that works even if disks are added and removed. See fstab(5).
>
> # <file system> <mount point> <type> <options>
> <dump> <pass>
> proc /proc proc
> nodev,noexec,nosuid 0 0
> /host/ubuntu/disks/root.disk / ext4
> loop,errors=remount-ro 0 1
> /host/ubuntu/disks/swap.disk none swap loop,sw
> 0 0
> - EOF -
>
> [ /boot/grub/grub.cfg ]
> ...
> menuentry 'Ubuntu, mit Linux 3.8.0-rc4-next20130121-1-iniza-generic'
> --class ubuntu --class gnu-linux --class gnu --class os {
> set gfxpayload=$linux_gfx_mode
> insmod part_msdos
> insmod ntfs
> set root='(hd0,msdos2)'
> search --no-floppy --fs-uuid --set=root 001AADA61AAD9964
> loopback loop0 /ubuntu/disks/root.disk
> set root=(loop0)
> linux /boot/vmlinuz-3.8.0-rc4-next20130121-1-iniza-generic
> root=UUID=001AADA61AAD9964 loop=/ubuntu/disks/root.disk ro
> initrd /boot/initrd.img-3.8.0-rc4-next20130121-1-iniza-generic
> }
> ...
>
Here some more useful outputs:
$ LC_ALL=C df -h -T
Filesystem Type Size Used Avail Use% Mounted on
rootfs rootfs 17G 15G 1.5G 92% /
udev devtmpfs 1.9G 12K 1.9G 1% /dev
tmpfs tmpfs 770M 892K 769M 1% /run
/dev/sda2 fuseblk 444G 81G 364G 19% /host
/dev/loop0 ext4 17G 15G 1.5G 92% /
none tmpfs 5.0M 0 5.0M 0% /run/lock
none tmpfs 1.9G 260K 1.9G 1% /run/shm
$ sudo LC_ALL=C fdisk -l /dev/sda
Disk /dev/sda: 500.1 GB, 500107862016 bytes
255 heads, 63 sectors/track, 60801 cylinders, total 976773168 sectors
Units = sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 4096 bytes
I/O size (minimum/optimal): 4096 bytes / 4096 bytes
Disk identifier: 0xcb9885ab
Device Boot Start End Blocks Id System
/dev/sda1 * 2048 206847 102400 7 HPFS/NTFS/exFAT
/dev/sda2 206848 931299327 465546240 7 HPFS/NTFS/exFAT
/dev/sda3 931299328 976773119 22736896 27 Hidden NTFS WinRE
I am still reflecting on any shitty userspace app is causing all the
trouble, but I have zero clue how to dig that...
- Sedat -
> Hope this helps you!
>
> Regards,
> - Sedat -
>
>> Honza
>> --
>> Jan Kara <jack@suse.cz>
>> SUSE Labs, CR
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-21 12:30 ` Sedat Dilek
@ 2013-01-21 14:07 ` Jan Kara
2013-01-21 14:28 ` Sedat Dilek
2013-01-21 23:04 ` Sedat Dilek
0 siblings, 2 replies; 26+ messages in thread
From: Jan Kara @ 2013-01-21 14:07 UTC (permalink / raw)
To: Sedat Dilek
Cc: Jan Kara, Eric Sandeen, linux-fsdevel, Ext4 Developers List,
Theodore Ts'o, LKML, linux-next, mszeredi
On Mon 21-01-13 13:30:26, Sedat Dilek wrote:
> On Mon, Jan 21, 2013 at 12:40 PM, Sedat Dilek <sedat.dilek@gmail.com> wrote:
> > On Mon, Jan 21, 2013 at 11:47 AM, Jan Kara <jack@suse.cz> wrote:
> >> The traces don't suggest an ext4/jbd2 problem. What is happening is that
> >> jbd2 is waiting for IO to finish and that never happens. Seeing that you
> >> loop device I'd think it's some interaction of the loop device and
> >> freezing. Can you reproduce the issue without the loop device (i.e. with
> >> the filesystem directly on e.g. scsi disk)? I suspect the reason is
> >> something like that the backing filesystem is already frozen so filesystem
> >> on top of it cannot write all the data and hangs waiting for IO -> suspend
> >> doesn't happen. Contents of /proc/mounts and losetup -l would help us
> >> understand what's going on.
> >>
> >
> > As said I am here in a very uncommon WUBI environment means my
> > Ubuntu/precise rootfs-image lays on the Win7-partition (NTFS).
> > Your explanation sounds reasonable to me as this line from my attached
> > testcase causes the troubles.
> >
> > echo mem > /sys/power/state && sleep 1
> >
> > So, /sys/ is not writable immediately after freezer ends
> >
> > I checked again and again my logs and have seen "starving" lines
> > reported by rtkit-daemon, but did not really get wiser what they want
> > to tell me. Stopping rtkit-daemon or resetting all or all-known
> > threads before running my pm_test/freezer did not help, too.
> >
> > /usr/sbin/rtkitctl --help
> > rtkitctl [options]
> >
> > -h, --help Show this help
> > --version Show version
> >
> > --reset-known Reset real-time status of known threads
> > --reset-all Reset real-time status of all threads
> > --start Start RealtimeKit if it is not running already
> > -k, --exit Terminate running RealtimeKit daemon
> >
> > Here are the outputs you wanted with some more (fstab, grub-config) etc.
> > I have here no -l option for losetup command.
> >
> >
> > - Sedat -
> >
> > P.S.: Outputs for Honza...
> >
> > $ sudo cat /proc/mounts
> > rootfs / rootfs rw 0 0
> > sysfs /sys sysfs rw,nosuid,nodev,noexec,relatime 0 0
> > proc /proc proc rw,nosuid,nodev,noexec,relatime 0 0
> > udev /dev devtmpfs rw,relatime,size=1966948k,nr_inodes=491737,mode=755 0 0
> > devpts /dev/pts devpts rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000 0 0
> > tmpfs /run tmpfs rw,nosuid,relatime,size=788076k,mode=755 0 0
> > /dev/sda2 /host fuseblk
> > rw,nosuid,nodev,relatime,user_id=0,group_id=0,allow_other,blksize=4096
> > 0 0
> > /dev/loop0 / ext4 rw,relatime,errors=remount-ro,data=ordered 0 0
> > none /sys/fs/fuse/connections fusectl rw,relatime 0 0
> > none /sys/kernel/debug debugfs rw,relatime 0 0
> > none /sys/kernel/security securityfs rw,relatime 0 0
> > none /run/lock tmpfs rw,nosuid,nodev,noexec,relatime,size=5120k 0 0
> > none /run/shm tmpfs rw,nosuid,nodev,relatime 0 0
> > gvfs-fuse-daemon /home/wearefam/.gvfs fuse.gvfs-fuse-daemon
> > rw,nosuid,nodev,relatime,user_id=1000,group_id=1000 0 0
> >
> > $ sudo losetup --all --verbose
> > /dev/loop0: [0802]:17982 (/host/ubuntu/disks/root.disk)
> >
> > $ sudo losetup --find --verbose
> > Loop device is /dev/loop1
> > /dev/loop1
> >
> > [ /etc/fstab ]
> > # /etc/fstab: static file system information.
> >
> > # Use 'blkid' to print the universally unique identifier for a
> > # device; this may be used with UUID= as a more robust way to name devices
> > # that works even if disks are added and removed. See fstab(5).
> >
> > # <file system> <mount point> <type> <options>
> > <dump> <pass>
> > proc /proc proc
> > nodev,noexec,nosuid 0 0
> > /host/ubuntu/disks/root.disk / ext4
> > loop,errors=remount-ro 0 1
> > /host/ubuntu/disks/swap.disk none swap loop,sw
> > 0 0
> > - EOF -
> >
> > [ /boot/grub/grub.cfg ]
> > ...
> > menuentry 'Ubuntu, mit Linux 3.8.0-rc4-next20130121-1-iniza-generic'
> > --class ubuntu --class gnu-linux --class gnu --class os {
> > set gfxpayload=$linux_gfx_mode
> > insmod part_msdos
> > insmod ntfs
> > set root='(hd0,msdos2)'
> > search --no-floppy --fs-uuid --set=root 001AADA61AAD9964
> > loopback loop0 /ubuntu/disks/root.disk
> > set root=(loop0)
> > linux /boot/vmlinuz-3.8.0-rc4-next20130121-1-iniza-generic
> > root=UUID=001AADA61AAD9964 loop=/ubuntu/disks/root.disk ro
> > initrd /boot/initrd.img-3.8.0-rc4-next20130121-1-iniza-generic
> > }
> > ...
> >
>
> Here some more useful outputs:
>
> $ LC_ALL=C df -h -T
> Filesystem Type Size Used Avail Use% Mounted on
> rootfs rootfs 17G 15G 1.5G 92% /
> udev devtmpfs 1.9G 12K 1.9G 1% /dev
> tmpfs tmpfs 770M 892K 769M 1% /run
> /dev/sda2 fuseblk 444G 81G 364G 19% /host
> /dev/loop0 ext4 17G 15G 1.5G 92% /
> none tmpfs 5.0M 0 5.0M 0% /run/lock
> none tmpfs 1.9G 260K 1.9G 1% /run/shm
>
> $ sudo LC_ALL=C fdisk -l /dev/sda
>
> Disk /dev/sda: 500.1 GB, 500107862016 bytes
> 255 heads, 63 sectors/track, 60801 cylinders, total 976773168 sectors
> Units = sectors of 1 * 512 = 512 bytes
> Sector size (logical/physical): 512 bytes / 4096 bytes
> I/O size (minimum/optimal): 4096 bytes / 4096 bytes
> Disk identifier: 0xcb9885ab
>
> Device Boot Start End Blocks Id System
> /dev/sda1 * 2048 206847 102400 7 HPFS/NTFS/exFAT
> /dev/sda2 206848 931299327 465546240 7 HPFS/NTFS/exFAT
> /dev/sda3 931299328 976773119 22736896 27 Hidden NTFS WinRE
>
> I am still reflecting on any shitty userspace app is causing all the
> trouble, but I have zero clue how to dig that...
Well, I think the outputs make it pretty clear. /dev/loop0 is a mounted
image from fuse filesystem. Fuse daemon making filesystem accessible gets
frozen before /dev/loop0 gets fully written out and so jbd2 journal thread
hangs. Maybe Miklos (added to CC) could fill in some details / ideas but I
think the setup like you have never really worked...
Honza
--
Jan Kara <jack@suse.cz>
SUSE Labs, CR
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-21 14:07 ` Jan Kara
@ 2013-01-21 14:28 ` Sedat Dilek
2013-01-21 17:39 ` Miklos Szeredi
2013-01-21 23:04 ` Sedat Dilek
1 sibling, 1 reply; 26+ messages in thread
From: Sedat Dilek @ 2013-01-21 14:28 UTC (permalink / raw)
To: Jan Kara
Cc: Eric Sandeen, linux-fsdevel, Ext4 Developers List,
Theodore Ts'o, LKML, linux-next, mszeredi
On Mon, Jan 21, 2013 at 3:07 PM, Jan Kara <jack@suse.cz> wrote:
> On Mon 21-01-13 13:30:26, Sedat Dilek wrote:
>> On Mon, Jan 21, 2013 at 12:40 PM, Sedat Dilek <sedat.dilek@gmail.com> wrote:
>> > On Mon, Jan 21, 2013 at 11:47 AM, Jan Kara <jack@suse.cz> wrote:
>> >> The traces don't suggest an ext4/jbd2 problem. What is happening is that
>> >> jbd2 is waiting for IO to finish and that never happens. Seeing that you
>> >> loop device I'd think it's some interaction of the loop device and
>> >> freezing. Can you reproduce the issue without the loop device (i.e. with
>> >> the filesystem directly on e.g. scsi disk)? I suspect the reason is
>> >> something like that the backing filesystem is already frozen so filesystem
>> >> on top of it cannot write all the data and hangs waiting for IO -> suspend
>> >> doesn't happen. Contents of /proc/mounts and losetup -l would help us
>> >> understand what's going on.
>> >>
>> >
>> > As said I am here in a very uncommon WUBI environment means my
>> > Ubuntu/precise rootfs-image lays on the Win7-partition (NTFS).
>> > Your explanation sounds reasonable to me as this line from my attached
>> > testcase causes the troubles.
>> >
>> > echo mem > /sys/power/state && sleep 1
>> >
>> > So, /sys/ is not writable immediately after freezer ends
>> >
>> > I checked again and again my logs and have seen "starving" lines
>> > reported by rtkit-daemon, but did not really get wiser what they want
>> > to tell me. Stopping rtkit-daemon or resetting all or all-known
>> > threads before running my pm_test/freezer did not help, too.
>> >
>> > /usr/sbin/rtkitctl --help
>> > rtkitctl [options]
>> >
>> > -h, --help Show this help
>> > --version Show version
>> >
>> > --reset-known Reset real-time status of known threads
>> > --reset-all Reset real-time status of all threads
>> > --start Start RealtimeKit if it is not running already
>> > -k, --exit Terminate running RealtimeKit daemon
>> >
>> > Here are the outputs you wanted with some more (fstab, grub-config) etc.
>> > I have here no -l option for losetup command.
>> >
>> >
>> > - Sedat -
>> >
>> > P.S.: Outputs for Honza...
>> >
>> > $ sudo cat /proc/mounts
>> > rootfs / rootfs rw 0 0
>> > sysfs /sys sysfs rw,nosuid,nodev,noexec,relatime 0 0
>> > proc /proc proc rw,nosuid,nodev,noexec,relatime 0 0
>> > udev /dev devtmpfs rw,relatime,size=1966948k,nr_inodes=491737,mode=755 0 0
>> > devpts /dev/pts devpts rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000 0 0
>> > tmpfs /run tmpfs rw,nosuid,relatime,size=788076k,mode=755 0 0
>> > /dev/sda2 /host fuseblk
>> > rw,nosuid,nodev,relatime,user_id=0,group_id=0,allow_other,blksize=4096
>> > 0 0
>> > /dev/loop0 / ext4 rw,relatime,errors=remount-ro,data=ordered 0 0
>> > none /sys/fs/fuse/connections fusectl rw,relatime 0 0
>> > none /sys/kernel/debug debugfs rw,relatime 0 0
>> > none /sys/kernel/security securityfs rw,relatime 0 0
>> > none /run/lock tmpfs rw,nosuid,nodev,noexec,relatime,size=5120k 0 0
>> > none /run/shm tmpfs rw,nosuid,nodev,relatime 0 0
>> > gvfs-fuse-daemon /home/wearefam/.gvfs fuse.gvfs-fuse-daemon
>> > rw,nosuid,nodev,relatime,user_id=1000,group_id=1000 0 0
>> >
>> > $ sudo losetup --all --verbose
>> > /dev/loop0: [0802]:17982 (/host/ubuntu/disks/root.disk)
>> >
>> > $ sudo losetup --find --verbose
>> > Loop device is /dev/loop1
>> > /dev/loop1
>> >
>> > [ /etc/fstab ]
>> > # /etc/fstab: static file system information.
>> >
>> > # Use 'blkid' to print the universally unique identifier for a
>> > # device; this may be used with UUID= as a more robust way to name devices
>> > # that works even if disks are added and removed. See fstab(5).
>> >
>> > # <file system> <mount point> <type> <options>
>> > <dump> <pass>
>> > proc /proc proc
>> > nodev,noexec,nosuid 0 0
>> > /host/ubuntu/disks/root.disk / ext4
>> > loop,errors=remount-ro 0 1
>> > /host/ubuntu/disks/swap.disk none swap loop,sw
>> > 0 0
>> > - EOF -
>> >
>> > [ /boot/grub/grub.cfg ]
>> > ...
>> > menuentry 'Ubuntu, mit Linux 3.8.0-rc4-next20130121-1-iniza-generic'
>> > --class ubuntu --class gnu-linux --class gnu --class os {
>> > set gfxpayload=$linux_gfx_mode
>> > insmod part_msdos
>> > insmod ntfs
>> > set root='(hd0,msdos2)'
>> > search --no-floppy --fs-uuid --set=root 001AADA61AAD9964
>> > loopback loop0 /ubuntu/disks/root.disk
>> > set root=(loop0)
>> > linux /boot/vmlinuz-3.8.0-rc4-next20130121-1-iniza-generic
>> > root=UUID=001AADA61AAD9964 loop=/ubuntu/disks/root.disk ro
>> > initrd /boot/initrd.img-3.8.0-rc4-next20130121-1-iniza-generic
>> > }
>> > ...
>> >
>>
>> Here some more useful outputs:
>>
>> $ LC_ALL=C df -h -T
>> Filesystem Type Size Used Avail Use% Mounted on
>> rootfs rootfs 17G 15G 1.5G 92% /
>> udev devtmpfs 1.9G 12K 1.9G 1% /dev
>> tmpfs tmpfs 770M 892K 769M 1% /run
>> /dev/sda2 fuseblk 444G 81G 364G 19% /host
>> /dev/loop0 ext4 17G 15G 1.5G 92% /
>> none tmpfs 5.0M 0 5.0M 0% /run/lock
>> none tmpfs 1.9G 260K 1.9G 1% /run/shm
>>
>> $ sudo LC_ALL=C fdisk -l /dev/sda
>>
>> Disk /dev/sda: 500.1 GB, 500107862016 bytes
>> 255 heads, 63 sectors/track, 60801 cylinders, total 976773168 sectors
>> Units = sectors of 1 * 512 = 512 bytes
>> Sector size (logical/physical): 512 bytes / 4096 bytes
>> I/O size (minimum/optimal): 4096 bytes / 4096 bytes
>> Disk identifier: 0xcb9885ab
>>
>> Device Boot Start End Blocks Id System
>> /dev/sda1 * 2048 206847 102400 7 HPFS/NTFS/exFAT
>> /dev/sda2 206848 931299327 465546240 7 HPFS/NTFS/exFAT
>> /dev/sda3 931299328 976773119 22736896 27 Hidden NTFS WinRE
>>
>> I am still reflecting on any shitty userspace app is causing all the
>> trouble, but I have zero clue how to dig that...
> Well, I think the outputs make it pretty clear. /dev/loop0 is a mounted
> image from fuse filesystem. Fuse daemon making filesystem accessible gets
> frozen before /dev/loop0 gets fully written out and so jbd2 journal thread
> hangs. Maybe Miklos (added to CC) could fill in some details / ideas but I
> think the setup like you have never really worked...
>
Thank you for the explanations.
Before doing some patches for Linux Test Project and replying to
LLVMLinux I was reflecting about FUSE when saw the 'df -h -T' line.
You might be right, that pm_test/freezer could never be OK here.
I wantend to test against Linux v3.8-rc4 to be sure.
Anyway, thanks for sharing your thoughts with me!
Let's see what Miklos says...
Regards,
- Sedat -
> Honza
> --
> Jan Kara <jack@suse.cz>
> SUSE Labs, CR
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-21 14:28 ` Sedat Dilek
@ 2013-01-21 17:39 ` Miklos Szeredi
0 siblings, 0 replies; 26+ messages in thread
From: Miklos Szeredi @ 2013-01-21 17:39 UTC (permalink / raw)
To: sedat.dilek
Cc: Jan Kara, Eric Sandeen, linux-fsdevel, Ext4 Developers List,
Theodore Ts'o, LKML, linux-next
On Mon, 2013-01-21 at 15:28 +0100, Sedat Dilek wrote:
> On Mon, Jan 21, 2013 at 3:07 PM, Jan Kara <jack@suse.cz> wrote:
> > Well, I think the outputs make it pretty clear. /dev/loop0 is a mounted
> > image from fuse filesystem. Fuse daemon making filesystem accessible gets
> > frozen before /dev/loop0 gets fully written out and so jbd2 journal thread
> > hangs. Maybe Miklos (added to CC) could fill in some details / ideas but I
> > think the setup like you have never really worked...
> >
>
> Thank you for the explanations.
> Before doing some patches for Linux Test Project and replying to
> LLVMLinux I was reflecting about FUSE when saw the 'df -h -T' line.
> You might be right, that pm_test/freezer could never be OK here.
> I wantend to test against Linux v3.8-rc4 to be sure.
> Anyway, thanks for sharing your thoughts with me!
There are several problems with this setup. Loop over fuse has always
been problematic because of interaction with the memory management.
E.g. the kernel is trying to allocate memory and is writing out dirty
pages to the loop device then that write ends up in the userspace
filesystem process which may want to allocate additional memory to
complete the write. This may end up deadlocking the writeout, which is
not good. So loop over fuse (for write) is not a good idea in any case.
One way to get around this limitation is to use mountlo, which does a
loop mount in userspace using UML and fuse. That will probably be
better.
Unfortunately fuse has a bad interaction with the freezer as well. The
reason for that is the freezer wants all syscalls to finish but with a
frozen userspace a fuse daemon will not be able to complete the work
necessary to finish those syscalls. We thought about this long and hard
and there are no easy solutions. We can allow the freezer to proceed
for cases when the syscall is directly waiting for a fuse filesystem
daemon reply. But the syscall may be waiting for the filesystem daemon
indirectly, e.g. sleeping on i_mutex, and that's rather more difficult
to fix. It's not impossible but it's a big project.
To conclude: writable loop over fuse is broken and was always broken,
it should not be used. Other solutions should work better but fuse is
currently not
Thanks,
Miklos
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-21 14:07 ` Jan Kara
2013-01-21 14:28 ` Sedat Dilek
@ 2013-01-21 23:04 ` Sedat Dilek
2013-01-21 23:11 ` Theodore Ts'o
1 sibling, 1 reply; 26+ messages in thread
From: Sedat Dilek @ 2013-01-21 23:04 UTC (permalink / raw)
To: Jan Kara
Cc: Eric Sandeen, linux-fsdevel, Ext4 Developers List,
Theodore Ts'o, LKML, linux-next, mszeredi
On Mon, Jan 21, 2013 at 3:07 PM, Jan Kara <jack@suse.cz> wrote:
> On Mon 21-01-13 13:30:26, Sedat Dilek wrote:
>> On Mon, Jan 21, 2013 at 12:40 PM, Sedat Dilek <sedat.dilek@gmail.com> wrote:
>> > On Mon, Jan 21, 2013 at 11:47 AM, Jan Kara <jack@suse.cz> wrote:
>> >> The traces don't suggest an ext4/jbd2 problem. What is happening is that
>> >> jbd2 is waiting for IO to finish and that never happens. Seeing that you
>> >> loop device I'd think it's some interaction of the loop device and
>> >> freezing. Can you reproduce the issue without the loop device (i.e. with
>> >> the filesystem directly on e.g. scsi disk)? I suspect the reason is
>> >> something like that the backing filesystem is already frozen so filesystem
>> >> on top of it cannot write all the data and hangs waiting for IO -> suspend
>> >> doesn't happen. Contents of /proc/mounts and losetup -l would help us
>> >> understand what's going on.
>> >>
>> >
>> > As said I am here in a very uncommon WUBI environment means my
>> > Ubuntu/precise rootfs-image lays on the Win7-partition (NTFS).
>> > Your explanation sounds reasonable to me as this line from my attached
>> > testcase causes the troubles.
>> >
>> > echo mem > /sys/power/state && sleep 1
>> >
>> > So, /sys/ is not writable immediately after freezer ends
>> >
>> > I checked again and again my logs and have seen "starving" lines
>> > reported by rtkit-daemon, but did not really get wiser what they want
>> > to tell me. Stopping rtkit-daemon or resetting all or all-known
>> > threads before running my pm_test/freezer did not help, too.
>> >
>> > /usr/sbin/rtkitctl --help
>> > rtkitctl [options]
>> >
>> > -h, --help Show this help
>> > --version Show version
>> >
>> > --reset-known Reset real-time status of known threads
>> > --reset-all Reset real-time status of all threads
>> > --start Start RealtimeKit if it is not running already
>> > -k, --exit Terminate running RealtimeKit daemon
>> >
>> > Here are the outputs you wanted with some more (fstab, grub-config) etc.
>> > I have here no -l option for losetup command.
>> >
>> >
>> > - Sedat -
>> >
>> > P.S.: Outputs for Honza...
>> >
>> > $ sudo cat /proc/mounts
>> > rootfs / rootfs rw 0 0
>> > sysfs /sys sysfs rw,nosuid,nodev,noexec,relatime 0 0
>> > proc /proc proc rw,nosuid,nodev,noexec,relatime 0 0
>> > udev /dev devtmpfs rw,relatime,size=1966948k,nr_inodes=491737,mode=755 0 0
>> > devpts /dev/pts devpts rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000 0 0
>> > tmpfs /run tmpfs rw,nosuid,relatime,size=788076k,mode=755 0 0
>> > /dev/sda2 /host fuseblk
>> > rw,nosuid,nodev,relatime,user_id=0,group_id=0,allow_other,blksize=4096
>> > 0 0
>> > /dev/loop0 / ext4 rw,relatime,errors=remount-ro,data=ordered 0 0
>> > none /sys/fs/fuse/connections fusectl rw,relatime 0 0
>> > none /sys/kernel/debug debugfs rw,relatime 0 0
>> > none /sys/kernel/security securityfs rw,relatime 0 0
>> > none /run/lock tmpfs rw,nosuid,nodev,noexec,relatime,size=5120k 0 0
>> > none /run/shm tmpfs rw,nosuid,nodev,relatime 0 0
>> > gvfs-fuse-daemon /home/wearefam/.gvfs fuse.gvfs-fuse-daemon
>> > rw,nosuid,nodev,relatime,user_id=1000,group_id=1000 0 0
>> >
>> > $ sudo losetup --all --verbose
>> > /dev/loop0: [0802]:17982 (/host/ubuntu/disks/root.disk)
>> >
>> > $ sudo losetup --find --verbose
>> > Loop device is /dev/loop1
>> > /dev/loop1
>> >
>> > [ /etc/fstab ]
>> > # /etc/fstab: static file system information.
>> >
>> > # Use 'blkid' to print the universally unique identifier for a
>> > # device; this may be used with UUID= as a more robust way to name devices
>> > # that works even if disks are added and removed. See fstab(5).
>> >
>> > # <file system> <mount point> <type> <options>
>> > <dump> <pass>
>> > proc /proc proc
>> > nodev,noexec,nosuid 0 0
>> > /host/ubuntu/disks/root.disk / ext4
>> > loop,errors=remount-ro 0 1
>> > /host/ubuntu/disks/swap.disk none swap loop,sw
>> > 0 0
>> > - EOF -
>> >
>> > [ /boot/grub/grub.cfg ]
>> > ...
>> > menuentry 'Ubuntu, mit Linux 3.8.0-rc4-next20130121-1-iniza-generic'
>> > --class ubuntu --class gnu-linux --class gnu --class os {
>> > set gfxpayload=$linux_gfx_mode
>> > insmod part_msdos
>> > insmod ntfs
>> > set root='(hd0,msdos2)'
>> > search --no-floppy --fs-uuid --set=root 001AADA61AAD9964
>> > loopback loop0 /ubuntu/disks/root.disk
>> > set root=(loop0)
>> > linux /boot/vmlinuz-3.8.0-rc4-next20130121-1-iniza-generic
>> > root=UUID=001AADA61AAD9964 loop=/ubuntu/disks/root.disk ro
>> > initrd /boot/initrd.img-3.8.0-rc4-next20130121-1-iniza-generic
>> > }
>> > ...
>> >
>>
>> Here some more useful outputs:
>>
>> $ LC_ALL=C df -h -T
>> Filesystem Type Size Used Avail Use% Mounted on
>> rootfs rootfs 17G 15G 1.5G 92% /
>> udev devtmpfs 1.9G 12K 1.9G 1% /dev
>> tmpfs tmpfs 770M 892K 769M 1% /run
>> /dev/sda2 fuseblk 444G 81G 364G 19% /host
>> /dev/loop0 ext4 17G 15G 1.5G 92% /
>> none tmpfs 5.0M 0 5.0M 0% /run/lock
>> none tmpfs 1.9G 260K 1.9G 1% /run/shm
>>
>> $ sudo LC_ALL=C fdisk -l /dev/sda
>>
>> Disk /dev/sda: 500.1 GB, 500107862016 bytes
>> 255 heads, 63 sectors/track, 60801 cylinders, total 976773168 sectors
>> Units = sectors of 1 * 512 = 512 bytes
>> Sector size (logical/physical): 512 bytes / 4096 bytes
>> I/O size (minimum/optimal): 4096 bytes / 4096 bytes
>> Disk identifier: 0xcb9885ab
>>
>> Device Boot Start End Blocks Id System
>> /dev/sda1 * 2048 206847 102400 7 HPFS/NTFS/exFAT
>> /dev/sda2 206848 931299327 465546240 7 HPFS/NTFS/exFAT
>> /dev/sda3 931299328 976773119 22736896 27 Hidden NTFS WinRE
>>
>> I am still reflecting on any shitty userspace app is causing all the
>> trouble, but I have zero clue how to dig that...
> Well, I think the outputs make it pretty clear. /dev/loop0 is a mounted
> image from fuse filesystem. Fuse daemon making filesystem accessible gets
> frozen before /dev/loop0 gets fully written out and so jbd2 journal thread
> hangs. Maybe Miklos (added to CC) could fill in some details / ideas but I
> think the setup like you have never really worked...
>
Beyond the FUSE/LOOP fun, will you apply this patch to your linux-next GIT tree?
Feel free to add...
Tested-by: Sedat Dilek <sedat.dilek@gmail.com>
A similiar patch for JBD went through your tree into mainline (see [1] and [2]).
Thanks!
- Sedat -
[1] http://git.kernel.org/?p=linux/kernel/git/jack/linux-fs.git;a=shortlog;h=refs/heads/for_next
[2] http://git.kernel.org/?p=linux/kernel/git/torvalds/linux.git;a=commitdiff;h=31db720643073571f15eede808486371556f6380
[3] http://git.kernel.org/?p=linux/kernel/git/torvalds/linux.git;a=commitdiff;h=7e2fb2d7e6a3094473f101ae33dd6431ae6d2ed1
> Honza
> --
> Jan Kara <jack@suse.cz>
> SUSE Labs, CR
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-21 23:04 ` Sedat Dilek
@ 2013-01-21 23:11 ` Theodore Ts'o
2013-01-21 23:29 ` Sedat Dilek
2013-01-22 23:50 ` Jan Kara
0 siblings, 2 replies; 26+ messages in thread
From: Theodore Ts'o @ 2013-01-21 23:11 UTC (permalink / raw)
To: Sedat Dilek
Cc: Jan Kara, Eric Sandeen, linux-fsdevel, Ext4 Developers List,
LKML, linux-next, mszeredi
On Tue, Jan 22, 2013 at 12:04:32AM +0100, Sedat Dilek wrote:
>
> Beyond the FUSE/LOOP fun, will you apply this patch to your linux-next GIT tree?
>
> Feel free to add...
>
> Tested-by: Sedat Dilek <sedat.dilek@gmail.com>
>
> A similiar patch for JBD went through your tree into mainline (see [1] and [2]).
I'm not at all convinced that this patch has anything to do with your
problem. I don't see how it could affect things, and I believe you
mentioned that you saw the problem even with this patch applied? (I'm
not sure; some of your messages which you sent were hard to
understand, and you mentioned something about trying to send messages
when low on sleep :-).
In any case, the reason why I haven't pulled this patch into the ext4
tree is because I was waiting for Eric and some of the performance
team folks at Red Hat to supply some additional information about why
this commit was making a difference in performance for a particular
proprietary, closed source benchmark.
I'm very suspicious about applying patches under the "cargo cult"
school of programming. ("We don't understand why it makes a
difference, but it seems to be good, so bombs away!" :-)
Regards,
- Ted
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-21 23:11 ` Theodore Ts'o
@ 2013-01-21 23:29 ` Sedat Dilek
2013-01-22 23:50 ` Jan Kara
1 sibling, 0 replies; 26+ messages in thread
From: Sedat Dilek @ 2013-01-21 23:29 UTC (permalink / raw)
To: Theodore Ts'o, Sedat Dilek, Jan Kara, Eric Sandeen,
linux-fsdevel, Ext4 Developers List, LKML, linux-next, mszeredi
On Tue, Jan 22, 2013 at 12:11 AM, Theodore Ts'o <tytso@mit.edu> wrote:
> On Tue, Jan 22, 2013 at 12:04:32AM +0100, Sedat Dilek wrote:
>>
>> Beyond the FUSE/LOOP fun, will you apply this patch to your linux-next GIT tree?
>>
>> Feel free to add...
>>
>> Tested-by: Sedat Dilek <sedat.dilek@gmail.com>
>>
>> A similiar patch for JBD went through your tree into mainline (see [1] and [2]).
>
> I'm not at all convinced that this patch has anything to do with your
> problem. I don't see how it could affect things, and I believe you
> mentioned that you saw the problem even with this patch applied? (I'm
> not sure; some of your messages which you sent were hard to
> understand, and you mentioned something about trying to send messages
> when low on sleep :-).
>
Even with little sleep I know what I have written.
YES, it didn't fix my problem but it also did not hurt my system.
I just run Linux Test Project w/o errors which also means nothing.
( Hmmm, I checked-out xfstests... did I compile it :-)? )
> In any case, the reason why I haven't pulled this patch into the ext4
> tree is because I was waiting for Eric and some of the performance
> team folks at Red Hat to supply some additional information about why
> this commit was making a difference in performance for a particular
> proprietary, closed source benchmark.
>
I am not following the linux-ext4/linux-fsdevel MLs so much, but IIRC
this patch is from December 2012.
An identical patch for JBD (approx. from same date) went upstream,
that's why I asked.
But now I know you care of JBD2 stuff :-).
Of course, I leave it to the experts to decide.
Come on Eric, open the pandora box and bomb Ted with logs and traces :-).
> I'm very suspicious about applying patches under the "cargo cult"
> school of programming. ("We don't understand why it makes a
> difference, but it seems to be good, so bombs away!" :-)
>
A good attitude - a man we can trust!
I would liked to see a more positive development on my issue.
But I still see no real reason to throw this WUBI installation away
hitting a "corner" case.
It was done as a temporary installation and made me happy in my daily
working life.
If I will get unhappy I boot into Win7, oops.
- Sedat -
> Regards,
>
> - Ted
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-21 23:11 ` Theodore Ts'o
2013-01-21 23:29 ` Sedat Dilek
@ 2013-01-22 23:50 ` Jan Kara
2013-01-23 1:37 ` Eric Sandeen
1 sibling, 1 reply; 26+ messages in thread
From: Jan Kara @ 2013-01-22 23:50 UTC (permalink / raw)
To: Theodore Ts'o
Cc: Sedat Dilek, Jan Kara, Eric Sandeen, linux-fsdevel,
Ext4 Developers List, LKML, linux-next, mszeredi
On Mon 21-01-13 18:11:30, Ted Tso wrote:
> On Tue, Jan 22, 2013 at 12:04:32AM +0100, Sedat Dilek wrote:
> >
> > Beyond the FUSE/LOOP fun, will you apply this patch to your linux-next GIT tree?
> >
> > Feel free to add...
> >
> > Tested-by: Sedat Dilek <sedat.dilek@gmail.com>
> >
> > A similiar patch for JBD went through your tree into mainline (see [1] and [2]).
>
> I'm not at all convinced that this patch has anything to do with your
> problem. I don't see how it could affect things, and I believe you
> mentioned that you saw the problem even with this patch applied? (I'm
> not sure; some of your messages which you sent were hard to
> understand, and you mentioned something about trying to send messages
> when low on sleep :-).
>
> In any case, the reason why I haven't pulled this patch into the ext4
> tree is because I was waiting for Eric and some of the performance
> team folks at Red Hat to supply some additional information about why
> this commit was making a difference in performance for a particular
> proprietary, closed source benchmark.
Just a small correction - it was aim7 AFAIK which isn't closed source
(anymore). You can download it from SourceForge
(http://sourceforge.net/projects/aimbench/files/aim-suite7/Initial%20release/).
Now I have some reservations about what the benchmark does but historically
it has found quite a few issues for us as well.
> I'm very suspicious about applying patches under the "cargo cult"
> school of programming. ("We don't understand why it makes a
> difference, but it seems to be good, so bombs away!" :-)
Well, neither am I ;) But it is obvious the patch speeds up
log_start_commit() by 'a bit' (taking spinlock, disabling irqs, ...). And
apparently 'a bit' is noticeable for particular workload on a particular
machine - commit statistics Eric provided showed that clearly. I'd still be
happier if Eric also told us how much log_start_commit() calls there were
so that one could verify that 'a bit' could indeed multiply to a measurable
difference. But given how simple the patch is, I gave away after a while
and just merged it...
Honza
--
Jan Kara <jack@suse.cz>
SUSE Labs, CR
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-22 23:50 ` Jan Kara
@ 2013-01-23 1:37 ` Eric Sandeen
2013-01-23 9:44 ` Jan Kara
0 siblings, 1 reply; 26+ messages in thread
From: Eric Sandeen @ 2013-01-23 1:37 UTC (permalink / raw)
To: Jan Kara
Cc: Theodore Ts'o, Sedat Dilek, linux-fsdevel,
Ext4 Developers List, LKML, linux-next, mszeredi
On 1/22/13 5:50 PM, Jan Kara wrote:
> On Mon 21-01-13 18:11:30, Ted Tso wrote:
>> On Tue, Jan 22, 2013 at 12:04:32AM +0100, Sedat Dilek wrote:
>>>
>>> Beyond the FUSE/LOOP fun, will you apply this patch to your linux-next GIT tree?
>>>
>>> Feel free to add...
>>>
>>> Tested-by: Sedat Dilek <sedat.dilek@gmail.com>
>>>
>>> A similiar patch for JBD went through your tree into mainline (see [1] and [2]).
>>
>> I'm not at all convinced that this patch has anything to do with your
>> problem. I don't see how it could affect things, and I believe you
>> mentioned that you saw the problem even with this patch applied? (I'm
>> not sure; some of your messages which you sent were hard to
>> understand, and you mentioned something about trying to send messages
>> when low on sleep :-).
>>
>> In any case, the reason why I haven't pulled this patch into the ext4
>> tree is because I was waiting for Eric and some of the performance
>> team folks at Red Hat to supply some additional information about why
>> this commit was making a difference in performance for a particular
>> proprietary, closed source benchmark.
> Just a small correction - it was aim7 AFAIK which isn't closed source
> (anymore). You can download it from SourceForge
> (http://sourceforge.net/projects/aimbench/files/aim-suite7/Initial%20release/).
> Now I have some reservations about what the benchmark does but historically
> it has found quite a few issues for us as well.
>
>> I'm very suspicious about applying patches under the "cargo cult"
>> school of programming. ("We don't understand why it makes a
>> difference, but it seems to be good, so bombs away!" :-)
> Well, neither am I ;) But it is obvious the patch speeds up
> log_start_commit() by 'a bit' (taking spinlock, disabling irqs, ...). And
> apparently 'a bit' is noticeable for particular workload on a particular
> machine - commit statistics Eric provided showed that clearly. I'd still be
> happier if Eric also told us how much log_start_commit() calls there were
> so that one could verify that 'a bit' could indeed multiply to a measurable
> difference. But given how simple the patch is, I gave away after a while
> and just merged it...
I am still trying to get our perf guys to collect that data, FWIW...
I will send it when I get it. I bugged them again today. :)
(Just to be sure: I was going to measure the wakeups the old way, and the
avoided wakeups with the new change; sound ok?)
-Eric
> Honza
>
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-23 1:37 ` Eric Sandeen
@ 2013-01-23 9:44 ` Jan Kara
2013-01-23 15:20 ` Eric Sandeen
0 siblings, 1 reply; 26+ messages in thread
From: Jan Kara @ 2013-01-23 9:44 UTC (permalink / raw)
To: Eric Sandeen
Cc: Jan Kara, Theodore Ts'o, Sedat Dilek, linux-fsdevel,
Ext4 Developers List, LKML, linux-next, mszeredi
On Tue 22-01-13 19:37:46, Eric Sandeen wrote:
> On 1/22/13 5:50 PM, Jan Kara wrote:
> > On Mon 21-01-13 18:11:30, Ted Tso wrote:
> >> On Tue, Jan 22, 2013 at 12:04:32AM +0100, Sedat Dilek wrote:
> >>>
> >>> Beyond the FUSE/LOOP fun, will you apply this patch to your linux-next GIT tree?
> >>>
> >>> Feel free to add...
> >>>
> >>> Tested-by: Sedat Dilek <sedat.dilek@gmail.com>
> >>>
> >>> A similiar patch for JBD went through your tree into mainline (see [1] and [2]).
> >>
> >> I'm not at all convinced that this patch has anything to do with your
> >> problem. I don't see how it could affect things, and I believe you
> >> mentioned that you saw the problem even with this patch applied? (I'm
> >> not sure; some of your messages which you sent were hard to
> >> understand, and you mentioned something about trying to send messages
> >> when low on sleep :-).
> >>
> >> In any case, the reason why I haven't pulled this patch into the ext4
> >> tree is because I was waiting for Eric and some of the performance
> >> team folks at Red Hat to supply some additional information about why
> >> this commit was making a difference in performance for a particular
> >> proprietary, closed source benchmark.
> > Just a small correction - it was aim7 AFAIK which isn't closed source
> > (anymore). You can download it from SourceForge
> > (http://sourceforge.net/projects/aimbench/files/aim-suite7/Initial%20release/).
> > Now I have some reservations about what the benchmark does but historically
> > it has found quite a few issues for us as well.
> >
> >> I'm very suspicious about applying patches under the "cargo cult"
> >> school of programming. ("We don't understand why it makes a
> >> difference, but it seems to be good, so bombs away!" :-)
> > Well, neither am I ;) But it is obvious the patch speeds up
> > log_start_commit() by 'a bit' (taking spinlock, disabling irqs, ...). And
> > apparently 'a bit' is noticeable for particular workload on a particular
> > machine - commit statistics Eric provided showed that clearly. I'd still be
> > happier if Eric also told us how much log_start_commit() calls there were
> > so that one could verify that 'a bit' could indeed multiply to a measurable
> > difference. But given how simple the patch is, I gave away after a while
> > and just merged it...
>
> I am still trying to get our perf guys to collect that data, FWIW...
> I will send it when I get it. I bugged them again today. :)
>
> (Just to be sure: I was going to measure the wakeups the old way, and the
> avoided wakeups with the new change; sound ok?)
Yes, that would be what I'm interested in.
Honza
--
Jan Kara <jack@suse.cz>
SUSE Labs, CR
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-23 9:44 ` Jan Kara
@ 2013-01-23 15:20 ` Eric Sandeen
2013-01-23 19:29 ` Jan Kara
0 siblings, 1 reply; 26+ messages in thread
From: Eric Sandeen @ 2013-01-23 15:20 UTC (permalink / raw)
To: Jan Kara
Cc: Theodore Ts'o, Sedat Dilek, linux-fsdevel,
Ext4 Developers List, LKML, linux-next, mszeredi
On 1/23/13 3:44 AM, Jan Kara wrote:
> On Tue 22-01-13 19:37:46, Eric Sandeen wrote:
>> On 1/22/13 5:50 PM, Jan Kara wrote:
>>> On Mon 21-01-13 18:11:30, Ted Tso wrote:
>>>> On Tue, Jan 22, 2013 at 12:04:32AM +0100, Sedat Dilek wrote:
>>>>>
>>>>> Beyond the FUSE/LOOP fun, will you apply this patch to your linux-next GIT tree?
>>>>>
>>>>> Feel free to add...
>>>>>
>>>>> Tested-by: Sedat Dilek <sedat.dilek@gmail.com>
>>>>>
>>>>> A similiar patch for JBD went through your tree into mainline (see [1] and [2]).
>>>>
>>>> I'm not at all convinced that this patch has anything to do with your
>>>> problem. I don't see how it could affect things, and I believe you
>>>> mentioned that you saw the problem even with this patch applied? (I'm
>>>> not sure; some of your messages which you sent were hard to
>>>> understand, and you mentioned something about trying to send messages
>>>> when low on sleep :-).
>>>>
>>>> In any case, the reason why I haven't pulled this patch into the ext4
>>>> tree is because I was waiting for Eric and some of the performance
>>>> team folks at Red Hat to supply some additional information about why
>>>> this commit was making a difference in performance for a particular
>>>> proprietary, closed source benchmark.
>>> Just a small correction - it was aim7 AFAIK which isn't closed source
>>> (anymore). You can download it from SourceForge
>>> (http://sourceforge.net/projects/aimbench/files/aim-suite7/Initial%20release/).
>>> Now I have some reservations about what the benchmark does but historically
>>> it has found quite a few issues for us as well.
>>>
>>>> I'm very suspicious about applying patches under the "cargo cult"
>>>> school of programming. ("We don't understand why it makes a
>>>> difference, but it seems to be good, so bombs away!" :-)
>>> Well, neither am I ;) But it is obvious the patch speeds up
>>> log_start_commit() by 'a bit' (taking spinlock, disabling irqs, ...). And
>>> apparently 'a bit' is noticeable for particular workload on a particular
>>> machine - commit statistics Eric provided showed that clearly. I'd still be
>>> happier if Eric also told us how much log_start_commit() calls there were
>>> so that one could verify that 'a bit' could indeed multiply to a measurable
>>> difference. But given how simple the patch is, I gave away after a while
>>> and just merged it...
>>
>> I am still trying to get our perf guys to collect that data, FWIW...
>> I will send it when I get it. I bugged them again today. :)
>>
>> (Just to be sure: I was going to measure the wakeups the old way, and the
>> avoided wakeups with the new change; sound ok?)
> Yes, that would be what I'm interested in.
Holy cow, this is much more than I expected, but here's what they report:
old JBD: AIM7 jobs/min 97624.39; got 78193 jbd wakeups
new JBD: AIM7 jobs/min 85929.43; got 6306999 jbd wakeups, 6264684 extra wakeups
The "extra wakeups" were hacked in like:
diff --git a/fs/jbd/journal.c b/fs/jbd/journal.c
index d492d57..3e0c4eb 100644
--- a/fs/jbd/journal.c
+++ b/fs/jbd/journal.c
@@ -433,15 +433,25 @@ int __log_space_left(journal_t *journal)
return left;
}
+unsigned long jbd_wakeups;
+unsigned long jbd_extra_wakeups;
+
/*
* Called under j_state_lock. Returns true if a transaction commit was started.
*/
int __log_start_commit(journal_t *journal, tid_t target)
{
/*
- * Are we already doing a recent enough commit?
+ * The only transaction we can possibly wait upon is the
+ * currently running transaction (if it exists). Otherwise,
+ * the target tid must be an old one.
*/
- if (!tid_geq(journal->j_commit_request, target)) {
+ if (/* journal->j_commit_request != target && <--- ERS: Undo "fix" */
+ journal->j_running_transaction &&
+ journal->j_running_transaction->t_tid == target) {
+ /* if we already have the right target, this is extra */
+ if (journal->j_commit_request == target)
+ jbd_extra_wakeups++;
/*
* We want a new commit: OK, mark the request and wakup the
* commit thread. We do _not_ do the commit ourselves.
@@ -451,9 +461,17 @@ int __log_start_commit(journal_t *journal, tid_t target)
jbd_debug(1, "JBD: requesting commit %d/%d\n",
journal->j_commit_request,
journal->j_commit_sequence);
+ jbd_wakeups++;
wake_up(&journal->j_wait_commit);
return 1;
- }
+ } else if (!tid_geq(journal->j_commit_request, target))
+ /* This should never happen, but if it does, preserve
+ the evidence before kjournald goes into a loop and
+ increments j_commit_sequence beyond all recognition. */
+ WARN_ONCE(1, "jbd: bad log_start_commit: %u %u %u %u\n",
+ journal->j_commit_request, journal->j_commit_sequence,
+ target, journal->j_running_transaction ?
+ journal->j_running_transaction->t_tid : 0);
return 0;
}
@@ -2039,6 +2057,7 @@ static void __exit journal_exit(void)
if (n)
printk(KERN_EMERG "JBD: leaked %d journal_heads!\n", n);
#endif
+ printk("got %lu jbd wakeups, %lu extra wakeups\n", jbd_wakeups, jbd_extra_wakeups);
jbd_remove_debugfs_entry();
journal_destroy_caches();
}
-Eric
> Honza
>
^ permalink raw reply related [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-23 15:20 ` Eric Sandeen
@ 2013-01-23 19:29 ` Jan Kara
2013-01-30 5:26 ` Theodore Ts'o
0 siblings, 1 reply; 26+ messages in thread
From: Jan Kara @ 2013-01-23 19:29 UTC (permalink / raw)
To: Eric Sandeen
Cc: Jan Kara, Theodore Ts'o, Sedat Dilek, linux-fsdevel,
Ext4 Developers List, LKML, linux-next, mszeredi
On Wed 23-01-13 09:20:38, Eric Sandeen wrote:
> On 1/23/13 3:44 AM, Jan Kara wrote:
> > On Tue 22-01-13 19:37:46, Eric Sandeen wrote:
> >> On 1/22/13 5:50 PM, Jan Kara wrote:
> >>> On Mon 21-01-13 18:11:30, Ted Tso wrote:
> >>>> On Tue, Jan 22, 2013 at 12:04:32AM +0100, Sedat Dilek wrote:
> >>>>>
> >>>>> Beyond the FUSE/LOOP fun, will you apply this patch to your linux-next GIT tree?
> >>>>>
> >>>>> Feel free to add...
> >>>>>
> >>>>> Tested-by: Sedat Dilek <sedat.dilek@gmail.com>
> >>>>>
> >>>>> A similiar patch for JBD went through your tree into mainline (see [1] and [2]).
> >>>>
> >>>> I'm not at all convinced that this patch has anything to do with your
> >>>> problem. I don't see how it could affect things, and I believe you
> >>>> mentioned that you saw the problem even with this patch applied? (I'm
> >>>> not sure; some of your messages which you sent were hard to
> >>>> understand, and you mentioned something about trying to send messages
> >>>> when low on sleep :-).
> >>>>
> >>>> In any case, the reason why I haven't pulled this patch into the ext4
> >>>> tree is because I was waiting for Eric and some of the performance
> >>>> team folks at Red Hat to supply some additional information about why
> >>>> this commit was making a difference in performance for a particular
> >>>> proprietary, closed source benchmark.
> >>> Just a small correction - it was aim7 AFAIK which isn't closed source
> >>> (anymore). You can download it from SourceForge
> >>> (http://sourceforge.net/projects/aimbench/files/aim-suite7/Initial%20release/).
> >>> Now I have some reservations about what the benchmark does but historically
> >>> it has found quite a few issues for us as well.
> >>>
> >>>> I'm very suspicious about applying patches under the "cargo cult"
> >>>> school of programming. ("We don't understand why it makes a
> >>>> difference, but it seems to be good, so bombs away!" :-)
> >>> Well, neither am I ;) But it is obvious the patch speeds up
> >>> log_start_commit() by 'a bit' (taking spinlock, disabling irqs, ...). And
> >>> apparently 'a bit' is noticeable for particular workload on a particular
> >>> machine - commit statistics Eric provided showed that clearly. I'd still be
> >>> happier if Eric also told us how much log_start_commit() calls there were
> >>> so that one could verify that 'a bit' could indeed multiply to a measurable
> >>> difference. But given how simple the patch is, I gave away after a while
> >>> and just merged it...
> >>
> >> I am still trying to get our perf guys to collect that data, FWIW...
> >> I will send it when I get it. I bugged them again today. :)
> >>
> >> (Just to be sure: I was going to measure the wakeups the old way, and the
> >> avoided wakeups with the new change; sound ok?)
> > Yes, that would be what I'm interested in.
>
> Holy cow, this is much more than I expected, but here's what they report:
>
> old JBD: AIM7 jobs/min 97624.39; got 78193 jbd wakeups
> new JBD: AIM7 jobs/min 85929.43; got 6306999 jbd wakeups, 6264684 extra wakeups
Yeah, that's a lot. My guess would be *a lot* of processes are hanging in
start_this_handle() and waiting for transaction commit. Each of them calls
__log_start_commit() and things add up. Thanks for getting these numbers.
Honza
--
Jan Kara <jack@suse.cz>
SUSE Labs, CR
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-23 19:29 ` Jan Kara
@ 2013-01-30 5:26 ` Theodore Ts'o
2013-01-30 5:39 ` [PATCH 1/2] " Theodore Ts'o
2013-01-30 10:07 ` jbd2: don't wake kjournald unnecessarily Jan Kara
0 siblings, 2 replies; 26+ messages in thread
From: Theodore Ts'o @ 2013-01-30 5:26 UTC (permalink / raw)
To: Jan Kara; +Cc: Eric Sandeen, Sedat Dilek, Ext4 Developers List, mszeredi
On Wed, Jan 23, 2013 at 08:29:11PM +0100, Jan Kara wrote:
> > old JBD: AIM7 jobs/min 97624.39; got 78193 jbd wakeups
> > new JBD: AIM7 jobs/min 85929.43; got 6306999 jbd wakeups, 6264684 extra wakeups
> Yeah, that's a lot. My guess would be *a lot* of processes are hanging in
> start_this_handle() and waiting for transaction commit. Each of them calls
> __log_start_commit() and things add up. Thanks for getting these numbers.
Yeah, wow. That would imply that there are a huge number of processes
that get hung up in start_this_handle(), and they are waking up the
journal before the kjournald has a chance to set T_LOCKED (since then
they would get blocked earlier in start_this_handle).
Given that, I wonder if the following change would actually help or
hurt things. Eric, would you be willing to ask your perf team to try
testing out these patches?
- Ted
^ permalink raw reply [flat|nested] 26+ messages in thread
* [PATCH 1/2] jbd2: don't wake kjournald unnecessarily
2013-01-30 5:26 ` Theodore Ts'o
@ 2013-01-30 5:39 ` Theodore Ts'o
2013-01-30 5:39 ` [PATCH 2/2] jbd2: commit as soon as possible after log_start_commit Theodore Ts'o
2013-01-30 10:07 ` jbd2: don't wake kjournald unnecessarily Jan Kara
1 sibling, 1 reply; 26+ messages in thread
From: Theodore Ts'o @ 2013-01-30 5:39 UTC (permalink / raw)
To: Ext4 Developers List
Cc: Theodore Ts'o, Eric Sandeen, Sedat Dilek, mszeredi
Don't send an extra wakeup to kjournald in the case where we
already have the proper target in j_commit_request, i.e. that
transaction has already been requested for commit.
commit deeeaf13 "jbd2: fix fsync() tid wraparound bug" changed
the logic leading to a wakeup, but it caused some extra wakeups
which were found to lead to a measurable performance regression.
Reported-by: Eric Sandeen <sandeen@redhat.com>
Signed-off-by: "Theodore Ts'o" <tytso@mit.edu>
Cc: Eric Sandeen <sandeen@redhat.com>
Cc: Sedat Dilek <sedat.dilek@gmail.com>
Cc: mszeredi@suse.cz
---
Eric,
I think this might be clearer than the patch which you proposed; what do
you think?
fs/jbd2/journal.c | 4 ++++
1 file changed, 4 insertions(+)
diff --git a/fs/jbd2/journal.c b/fs/jbd2/journal.c
index dbf41f9..1a80e31 100644
--- a/fs/jbd2/journal.c
+++ b/fs/jbd2/journal.c
@@ -513,6 +513,10 @@ int __jbd2_log_space_left(journal_t *journal)
*/
int __jbd2_log_start_commit(journal_t *journal, tid_t target)
{
+ /* Return if the txn has already requested to be committed */
+ if (journal->j_commit_request == target)
+ return 0;
+
/*
* The only transaction we can possibly wait upon is the
* currently running transaction (if it exists). Otherwise,
--
1.7.12.rc0.22.gcdd159b
^ permalink raw reply related [flat|nested] 26+ messages in thread
* [PATCH 2/2] jbd2: commit as soon as possible after log_start_commit
2013-01-30 5:39 ` [PATCH 1/2] " Theodore Ts'o
@ 2013-01-30 5:39 ` Theodore Ts'o
2013-02-02 19:33 ` Andreas Dilger
0 siblings, 1 reply; 26+ messages in thread
From: Theodore Ts'o @ 2013-01-30 5:39 UTC (permalink / raw)
To: Ext4 Developers List
Cc: Theodore Ts'o, Eric Sandeen, Sedat Dilek, mszeredi
Once a transaction has been requested to be committed, don't let any
other handles start under that transaction, and don't allow any
pending transactions to be extended (i.e., in the case of
unlink/ftruncate).
The idea is once the transaction has had log_start_commit() called on
it, at least one thread is blocked waiting for that transaction to
commit, and over time, more and more threads will end up getting
blocked. In order to avoid high variability in file system operations
getting blocked behind the a blocked start_this_handle(), we should
try to get the commit started as soon as possible.
Signed-off-by: "Theodore Ts'o" <tytso@mit.edu>
Cc: Eric Sandeen <sandeen@redhat.com>
Cc: Sedat Dilek <sedat.dilek@gmail.com>
Cc: mszeredi@suse.cz
---
fs/jbd2/commit.c | 3 ++-
fs/jbd2/journal.c | 1 +
fs/jbd2/transaction.c | 6 ++++--
include/linux/jbd2.h | 1 +
4 files changed, 8 insertions(+), 3 deletions(-)
diff --git a/fs/jbd2/commit.c b/fs/jbd2/commit.c
index 3091d42..fd2ac94 100644
--- a/fs/jbd2/commit.c
+++ b/fs/jbd2/commit.c
@@ -424,7 +424,8 @@ void jbd2_journal_commit_transaction(journal_t *journal)
J_ASSERT(journal->j_committing_transaction == NULL);
commit_transaction = journal->j_running_transaction;
- J_ASSERT(commit_transaction->t_state == T_RUNNING);
+ J_ASSERT(commit_transaction->t_state == T_REQUESTED ||
+ commit_transaction->t_state == T_RUNNING);
trace_jbd2_start_commit(journal, commit_transaction);
jbd_debug(1, "JBD2: starting commit of transaction %d\n",
diff --git a/fs/jbd2/journal.c b/fs/jbd2/journal.c
index 1a80e31..c22773b 100644
--- a/fs/jbd2/journal.c
+++ b/fs/jbd2/journal.c
@@ -533,6 +533,7 @@ int __jbd2_log_start_commit(journal_t *journal, tid_t target)
jbd_debug(1, "JBD2: requesting commit %d/%d\n",
journal->j_commit_request,
journal->j_commit_sequence);
+ journal->j_running_transaction->t_state = T_REQUESTED;
wake_up(&journal->j_wait_commit);
return 1;
} else if (!tid_geq(journal->j_commit_request, target))
diff --git a/fs/jbd2/transaction.c b/fs/jbd2/transaction.c
index df9f297..6daff29 100644
--- a/fs/jbd2/transaction.c
+++ b/fs/jbd2/transaction.c
@@ -224,7 +224,8 @@ repeat:
* If the current transaction is locked down for commit, wait for the
* lock to be released.
*/
- if (transaction->t_state == T_LOCKED) {
+ if ((transaction->t_state == T_LOCKED) ||
+ (transaction->t_state == T_REQUESTED)) {
DEFINE_WAIT(wait);
prepare_to_wait(&journal->j_wait_transaction_locked,
@@ -2179,7 +2180,8 @@ void __jbd2_journal_refile_buffer(struct journal_head *jh)
else
jlist = BJ_Reserved;
__jbd2_journal_file_buffer(jh, jh->b_transaction, jlist);
- J_ASSERT_JH(jh, jh->b_transaction->t_state == T_RUNNING);
+ J_ASSERT_JH(jh, (jh->b_transaction->t_state == T_RUNNING ||
+ jh->b_transaction->t_state == T_REQUESTED));
if (was_dirty)
set_buffer_jbddirty(bh);
diff --git a/include/linux/jbd2.h b/include/linux/jbd2.h
index e30b663..920a8d0 100644
--- a/include/linux/jbd2.h
+++ b/include/linux/jbd2.h
@@ -493,6 +493,7 @@ struct transaction_s
*/
enum {
T_RUNNING,
+ T_REQUESTED,
T_LOCKED,
T_FLUSH,
T_COMMIT,
--
1.7.12.rc0.22.gcdd159b
^ permalink raw reply related [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-30 5:26 ` Theodore Ts'o
2013-01-30 5:39 ` [PATCH 1/2] " Theodore Ts'o
@ 2013-01-30 10:07 ` Jan Kara
2013-01-30 10:29 ` Sedat Dilek
1 sibling, 1 reply; 26+ messages in thread
From: Jan Kara @ 2013-01-30 10:07 UTC (permalink / raw)
To: Theodore Ts'o
Cc: Jan Kara, Eric Sandeen, Sedat Dilek, Ext4 Developers List, mszeredi
On Wed 30-01-13 00:26:58, Ted Tso wrote:
> On Wed, Jan 23, 2013 at 08:29:11PM +0100, Jan Kara wrote:
> > > old JBD: AIM7 jobs/min 97624.39; got 78193 jbd wakeups
> > > new JBD: AIM7 jobs/min 85929.43; got 6306999 jbd wakeups, 6264684 extra wakeups
> > Yeah, that's a lot. My guess would be *a lot* of processes are hanging in
> > start_this_handle() and waiting for transaction commit. Each of them calls
> > __log_start_commit() and things add up. Thanks for getting these numbers.
>
> Yeah, wow. That would imply that there are a huge number of processes
> that get hung up in start_this_handle(), and they are waking up the
> journal before the kjournald has a chance to set T_LOCKED (since then
> they would get blocked earlier in start_this_handle).
>
> Given that, I wonder if the following change would actually help or
> hurt things. Eric, would you be willing to ask your perf team to try
> testing out these patches?
Umm, I don't see anything. Forgot to attach them?
Honza
--
Jan Kara <jack@suse.cz>
SUSE Labs, CR
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-30 10:07 ` jbd2: don't wake kjournald unnecessarily Jan Kara
@ 2013-01-30 10:29 ` Sedat Dilek
2013-01-30 10:41 ` Jan Kara
0 siblings, 1 reply; 26+ messages in thread
From: Sedat Dilek @ 2013-01-30 10:29 UTC (permalink / raw)
To: Jan Kara; +Cc: Theodore Ts'o, Eric Sandeen, Ext4 Developers List, mszeredi
On Wed, Jan 30, 2013 at 11:07 AM, Jan Kara <jack@suse.cz> wrote:
> On Wed 30-01-13 00:26:58, Ted Tso wrote:
>> On Wed, Jan 23, 2013 at 08:29:11PM +0100, Jan Kara wrote:
>> > > old JBD: AIM7 jobs/min 97624.39; got 78193 jbd wakeups
>> > > new JBD: AIM7 jobs/min 85929.43; got 6306999 jbd wakeups, 6264684 extra wakeups
>> > Yeah, that's a lot. My guess would be *a lot* of processes are hanging in
>> > start_this_handle() and waiting for transaction commit. Each of them calls
>> > __log_start_commit() and things add up. Thanks for getting these numbers.
>>
>> Yeah, wow. That would imply that there are a huge number of processes
>> that get hung up in start_this_handle(), and they are waking up the
>> journal before the kjournald has a chance to set T_LOCKED (since then
>> they would get blocked earlier in start_this_handle).
>>
>> Given that, I wonder if the following change would actually help or
>> hurt things. Eric, would you be willing to ask your perf team to try
>> testing out these patches?
> Umm, I don't see anything. Forgot to attach them?
>
Here I catched the two patches:
http://patchwork.ozlabs.org/patch/216768/
http://patchwork.ozlabs.org/patch/216767/
- Sedat -
> Honza
> --
> Jan Kara <jack@suse.cz>
> SUSE Labs, CR
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: jbd2: don't wake kjournald unnecessarily
2013-01-30 10:29 ` Sedat Dilek
@ 2013-01-30 10:41 ` Jan Kara
0 siblings, 0 replies; 26+ messages in thread
From: Jan Kara @ 2013-01-30 10:41 UTC (permalink / raw)
To: Sedat Dilek
Cc: Jan Kara, Theodore Ts'o, Eric Sandeen, Ext4 Developers List,
mszeredi
On Wed 30-01-13 11:29:02, Sedat Dilek wrote:
> On Wed, Jan 30, 2013 at 11:07 AM, Jan Kara <jack@suse.cz> wrote:
> > On Wed 30-01-13 00:26:58, Ted Tso wrote:
> >> On Wed, Jan 23, 2013 at 08:29:11PM +0100, Jan Kara wrote:
> >> > > old JBD: AIM7 jobs/min 97624.39; got 78193 jbd wakeups
> >> > > new JBD: AIM7 jobs/min 85929.43; got 6306999 jbd wakeups, 6264684 extra wakeups
> >> > Yeah, that's a lot. My guess would be *a lot* of processes are hanging in
> >> > start_this_handle() and waiting for transaction commit. Each of them calls
> >> > __log_start_commit() and things add up. Thanks for getting these numbers.
> >>
> >> Yeah, wow. That would imply that there are a huge number of processes
> >> that get hung up in start_this_handle(), and they are waking up the
> >> journal before the kjournald has a chance to set T_LOCKED (since then
> >> they would get blocked earlier in start_this_handle).
> >>
> >> Given that, I wonder if the following change would actually help or
> >> hurt things. Eric, would you be willing to ask your perf team to try
> >> testing out these patches?
> > Umm, I don't see anything. Forgot to attach them?
> >
>
> Here I catched the two patches:
>
> http://patchwork.ozlabs.org/patch/216768/
> http://patchwork.ozlabs.org/patch/216767/
Ah, OK. Thanks for the pointer.
Honza
--
Jan Kara <jack@suse.cz>
SUSE Labs, CR
^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [PATCH 2/2] jbd2: commit as soon as possible after log_start_commit
2013-01-30 5:39 ` [PATCH 2/2] jbd2: commit as soon as possible after log_start_commit Theodore Ts'o
@ 2013-02-02 19:33 ` Andreas Dilger
0 siblings, 0 replies; 26+ messages in thread
From: Andreas Dilger @ 2013-02-02 19:33 UTC (permalink / raw)
To: Theodore Ts'o
Cc: Ext4 Developers List, Eric Sandeen, Sedat Dilek, mszeredi
On 2013-01-29, at 10:39 PM, Theodore Ts'o wrote:
> Once a transaction has been requested to be committed, don't let any
> other handles start under that transaction, and don't allow any
> pending transactions to be extended (i.e., in the case of
> unlink/ftruncate).
>
> The idea is once the transaction has had log_start_commit() called on
> it, at least one thread is blocked waiting for that transaction to
> commit, and over time, more and more threads will end up getting
> blocked. In order to avoid high variability in file system operations
> getting blocked behind the a blocked start_this_handle(), we should
> try to get the commit started as soon as possible.
I was thinking this could break transaction batching from multiple
threads, which would hurt performance significantly in a multi-
threaded sync-heavy workload.
However, it seems that jbd2_journal_stop() blocks the h_sync thread
before it calls jbd2_log_start_commit(), so it looks like it should
be OK.
You can add my:
Acked-by: Andreas Dilger <adilger@dilger.ca>
>
> Signed-off-by: "Theodore Ts'o" <tytso@mit.edu>
> Cc: Eric Sandeen <sandeen@redhat.com>
> Cc: Sedat Dilek <sedat.dilek@gmail.com>
> Cc: mszeredi@suse.cz
> ---
> fs/jbd2/commit.c | 3 ++-
> fs/jbd2/journal.c | 1 +
> fs/jbd2/transaction.c | 6 ++++--
> include/linux/jbd2.h | 1 +
> 4 files changed, 8 insertions(+), 3 deletions(-)
>
> diff --git a/fs/jbd2/commit.c b/fs/jbd2/commit.c
> index 3091d42..fd2ac94 100644
> --- a/fs/jbd2/commit.c
> +++ b/fs/jbd2/commit.c
> @@ -424,7 +424,8 @@ void jbd2_journal_commit_transaction(journal_t *journal)
> J_ASSERT(journal->j_committing_transaction == NULL);
>
> commit_transaction = journal->j_running_transaction;
> - J_ASSERT(commit_transaction->t_state == T_RUNNING);
> + J_ASSERT(commit_transaction->t_state == T_REQUESTED ||
> + commit_transaction->t_state == T_RUNNING);
>
> trace_jbd2_start_commit(journal, commit_transaction);
> jbd_debug(1, "JBD2: starting commit of transaction %d\n",
> diff --git a/fs/jbd2/journal.c b/fs/jbd2/journal.c
> index 1a80e31..c22773b 100644
> --- a/fs/jbd2/journal.c
> +++ b/fs/jbd2/journal.c
> @@ -533,6 +533,7 @@ int __jbd2_log_start_commit(journal_t *journal, tid_t target)
> jbd_debug(1, "JBD2: requesting commit %d/%d\n",
> journal->j_commit_request,
> journal->j_commit_sequence);
> + journal->j_running_transaction->t_state = T_REQUESTED;
> wake_up(&journal->j_wait_commit);
> return 1;
> } else if (!tid_geq(journal->j_commit_request, target))
> diff --git a/fs/jbd2/transaction.c b/fs/jbd2/transaction.c
> index df9f297..6daff29 100644
> --- a/fs/jbd2/transaction.c
> +++ b/fs/jbd2/transaction.c
> @@ -224,7 +224,8 @@ repeat:
> * If the current transaction is locked down for commit, wait for the
> * lock to be released.
> */
> - if (transaction->t_state == T_LOCKED) {
> + if ((transaction->t_state == T_LOCKED) ||
> + (transaction->t_state == T_REQUESTED)) {
> DEFINE_WAIT(wait);
>
> prepare_to_wait(&journal->j_wait_transaction_locked,
> @@ -2179,7 +2180,8 @@ void __jbd2_journal_refile_buffer(struct journal_head *jh)
> else
> jlist = BJ_Reserved;
> __jbd2_journal_file_buffer(jh, jh->b_transaction, jlist);
> - J_ASSERT_JH(jh, jh->b_transaction->t_state == T_RUNNING);
> + J_ASSERT_JH(jh, (jh->b_transaction->t_state == T_RUNNING ||
> + jh->b_transaction->t_state == T_REQUESTED));
>
> if (was_dirty)
> set_buffer_jbddirty(bh);
> diff --git a/include/linux/jbd2.h b/include/linux/jbd2.h
> index e30b663..920a8d0 100644
> --- a/include/linux/jbd2.h
> +++ b/include/linux/jbd2.h
> @@ -493,6 +493,7 @@ struct transaction_s
> */
> enum {
> T_RUNNING,
> + T_REQUESTED,
> T_LOCKED,
> T_FLUSH,
> T_COMMIT,
> --
> 1.7.12.rc0.22.gcdd159b
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-ext4" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 26+ messages in thread
end of thread, other threads:[~2013-02-02 19:33 UTC | newest]
Thread overview: 26+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2013-01-19 23:44 jbd2: don't wake kjournald unnecessarily Sedat Dilek
2013-01-20 0:06 ` Sedat Dilek
2013-01-20 0:35 ` Sedat Dilek
2013-01-20 0:55 ` Sedat Dilek
2013-01-21 10:47 ` Jan Kara
2013-01-21 11:40 ` Sedat Dilek
2013-01-21 12:30 ` Sedat Dilek
2013-01-21 14:07 ` Jan Kara
2013-01-21 14:28 ` Sedat Dilek
2013-01-21 17:39 ` Miklos Szeredi
2013-01-21 23:04 ` Sedat Dilek
2013-01-21 23:11 ` Theodore Ts'o
2013-01-21 23:29 ` Sedat Dilek
2013-01-22 23:50 ` Jan Kara
2013-01-23 1:37 ` Eric Sandeen
2013-01-23 9:44 ` Jan Kara
2013-01-23 15:20 ` Eric Sandeen
2013-01-23 19:29 ` Jan Kara
2013-01-30 5:26 ` Theodore Ts'o
2013-01-30 5:39 ` [PATCH 1/2] " Theodore Ts'o
2013-01-30 5:39 ` [PATCH 2/2] jbd2: commit as soon as possible after log_start_commit Theodore Ts'o
2013-02-02 19:33 ` Andreas Dilger
2013-01-30 10:07 ` jbd2: don't wake kjournald unnecessarily Jan Kara
2013-01-30 10:29 ` Sedat Dilek
2013-01-30 10:41 ` Jan Kara
2013-01-21 12:02 ` Carlos Maiolino
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.