* 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 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: [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
* 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: 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
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.