Linux

It is interesting how a user-space task could lead to hinder a Linux kernel software suspend operation.

[11735.155443] PM: suspend entry (deep)
[11735.155445] PM: Syncing filesystems ... done.
[11735.215091] [drm:wait_panel_status [i915]] *ERROR* PPS state mismatch
[11735.215172] [drm:wait_panel_status [i915]] *ERROR* PPS state mismatch
[11735.558676] rfkill: input handler enabled
[11735.608859] (NULL device *): firmware: direct-loading firmware rtlwifi/rtl8723befw_36.bin
[11735.609910] (NULL device *): firmware: direct-loading firmware rtl_bt/rtl8723b_fw.bin
[11735.611871] Freezing user space processes ... 
[11755.615603] Freezing of tasks failed after 20.003 seconds (1 tasks refusing to freeze, wq_busy=0):
[11755.615854] digikam         D    0 13262  13245 0x00000004
[11755.615859] Call Trace:
[11755.615873]  __schedule+0x28e/0x880
[11755.615878]  schedule+0x2c/0x80
[11755.615889]  request_wait_answer+0xa3/0x220 [fuse]
[11755.615895]  ? finish_wait+0x80/0x80
[11755.615902]  __fuse_request_send+0x86/0x90 [fuse]
[11755.615907]  fuse_request_send+0x27/0x30 [fuse]
[11755.615914]  fuse_send_readpages.isra.30+0xd1/0x120 [fuse]
[11755.615920]  fuse_readpages+0xfd/0x110 [fuse]
[11755.615928]  __do_page_cache_readahead+0x200/0x2d0
[11755.615936]  filemap_fault+0x37b/0x640
[11755.615940]  ? filemap_fault+0x37b/0x640
[11755.615944]  ? filemap_map_pages+0x179/0x320
[11755.615950]  __do_fault+0x1e/0xb0
[11755.615953]  __handle_mm_fault+0xc8a/0x1160
[11755.615958]  handle_mm_fault+0xb1/0x200
[11755.615964]  __do_page_fault+0x257/0x4d0
[11755.615968]  do_page_fault+0x2e/0xd0
[11755.615973]  page_fault+0x22/0x30
[11755.615976] RIP: 0033:0x7f32d3c7ff90
[11755.615978] RSP: 002b:00007ffd887c9d18 EFLAGS: 00010246
[11755.615981] RAX: 00007f32d3fc9c50 RBX: 000000000275e440 RCX: 0000000000000003
[11755.615982] RDX: 0000000000000002 RSI: 00007ffd887c9f10 RDI: 000000000275e440
[11755.615984] RBP: 00007ffd887c9f10 R08: 000000000275e820 R09: 00000000018d2f40
[11755.615986] R10: 0000000000000002 R11: 0000000000000000 R12: 000000000189cbc0
[11755.615987] R13: 0000000001839dc0 R14: 000000000275e440 R15: 0000000000000000
[11755.616014] OOM killer enabled.
[11755.616015] Restarting tasks ... done.
[11755.817640] PM: suspend exit
[11755.817698] PM: suspend entry (s2idle)
[11755.817700] PM: Syncing filesystems ... done.
[11755.983156] rfkill: input handler disabled
[11756.030209] rfkill: input handler enabled
[11756.073529] Freezing user space processes ... 
[11776.084309] Freezing of tasks failed after 20.010 seconds (2 tasks refusing to freeze, wq_busy=0):
[11776.084630] digikam         D    0 13262  13245 0x00000004
[11776.084636] Call Trace:
[11776.084653]  __schedule+0x28e/0x880
[11776.084659]  schedule+0x2c/0x80
[11776.084672]  request_wait_answer+0xa3/0x220 [fuse]
[11776.084680]  ? finish_wait+0x80/0x80
[11776.084688]  __fuse_request_send+0x86/0x90 [fuse]
[11776.084695]  fuse_request_send+0x27/0x30 [fuse]
[11776.084703]  fuse_send_readpages.isra.30+0xd1/0x120 [fuse]
[11776.084711]  fuse_readpages+0xfd/0x110 [fuse]
[11776.084721]  __do_page_cache_readahead+0x200/0x2d0
[11776.084730]  filemap_fault+0x37b/0x640
[11776.084735]  ? filemap_fault+0x37b/0x640
[11776.084743]  ? __update_load_avg_blocked_se.isra.33+0xa1/0xf0
[11776.084749]  ? filemap_map_pages+0x179/0x320
[11776.084755]  __do_fault+0x1e/0xb0
[11776.084759]  __handle_mm_fault+0xc8a/0x1160
[11776.084765]  handle_mm_fault+0xb1/0x200
[11776.084772]  __do_page_fault+0x257/0x4d0
[11776.084777]  do_page_fault+0x2e/0xd0
[11776.084783]  page_fault+0x22/0x30
[11776.084787] RIP: 0033:0x7f31ddf315e0
[11776.084789] RSP: 002b:00007ffd887ca068 EFLAGS: 00010202
[11776.084793] RAX: 00007f31de13c350 RBX: 00000000040be3f0 RCX: 000000000283da60
[11776.084795] RDX: 0000000000000001 RSI: 00000000040be3f0 RDI: 00000000040be3f0
[11776.084797] RBP: 00007f32d3fca1e0 R08: 0000000005679250 R09: 0000000000000020
[11776.084799] R10: 00000000058fc1b0 R11: 0000000004b9ac50 R12: 0000000000000000
[11776.084801] R13: 0000000000000001 R14: 0000000000000000 R15: 0000000000000000
[11776.084806] QXcbEventReader D    0 13268  13245 0x00000004
[11776.084810] Call Trace:
[11776.084817]  __schedule+0x28e/0x880
[11776.084823]  schedule+0x2c/0x80
[11776.084827]  rwsem_down_write_failed_killable+0x25a/0x490
[11776.084832]  call_rwsem_down_write_failed_killable+0x17/0x30
[11776.084836]  ? call_rwsem_down_write_failed_killable+0x17/0x30
[11776.084842]  down_write_killable+0x2d/0x50
[11776.084848]  do_mprotect_pkey+0xa9/0x2f0
[11776.084854]  SyS_mprotect+0x13/0x20
[11776.084859]  system_call_fast_compare_end+0xc/0x97
[11776.084861] RIP: 0033:0x7f32d1f7c057
[11776.084863] RSP: 002b:00007f32cbb8c8d8 EFLAGS: 00000206 ORIG_RAX: 000000000000000a
[11776.084867] RAX: ffffffffffffffda RBX: 00007f32c4000020 RCX: 00007f32d1f7c057
[11776.084869] RDX: 0000000000000003 RSI: 0000000000001000 RDI: 00007f32c4024000
[11776.084871] RBP: 00000000000000c5 R08: 00007f32c4000000 R09: 0000000000024000
[11776.084872] R10: 00007f32c4024000 R11: 0000000000000206 R12: 00000000000000a0
[11776.084874] R13: 00007f32c4022f60 R14: 0000000000001000 R15: 00000000000000e0
[11776.084906] OOM killer enabled.
[11776.084907] Restarting tasks ... done.
[11776.289655] PM: suspend exit
[11776.459624] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[11776.469521] rfkill: input handler disabled
[11776.978733] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[11777.038879] IPv6: ADDRCONF(NETDEV_UP): wlp1s0: link is not ready
[11778.022062] wlp1s0: authenticate with 50:8f:4c:82:4d:dd
[11778.033155] wlp1s0: send auth to 50:8f:4c:82:4d:dd (try 1/3)
[11778.038522] wlp1s0: authenticated
[11778.041511] wlp1s0: associate with 50:8f:4c:82:4d:dd (try 1/3)
[11778.059860] wlp1s0: RX AssocResp from 50:8f:4c:82:4d:dd (capab=0x431 status=0 aid=5)
[11778.060253] wlp1s0: associated
[11778.060308] IPv6: ADDRCONF(NETDEV_CHANGE): wlp1s0: link becomes ready
[11778.987669] [drm:wait_panel_status [i915]] *ERROR* PPS state mismatch
[11779.117608] [drm:wait_panel_status [i915]] *ERROR* PPS state mismatch
[11779.160930] [drm:wait_panel_status [i915]] *ERROR* PPS state mismatch
[11779.784045] [drm:wait_panel_status [i915]] *ERROR* PPS state mismatch
[11779.913668] [drm:wait_panel_status [i915]] *ERROR* PPS state mismatch
[11779.961517] [drm:wait_panel_status [i915]] *ERROR* PPS state mismatch
11:58 ♒♒♒   ☺    

Bugs can be annoying. Especially the ones that crash or hang and do not have a root cause. A good example of such annoyance can be kernel bugs, where a faulty hardware/device driver hinders the kernel’s suspend/resume process. Because, as a user, while in the middle of your work, you suspend your machine hoping to resume your work, back when at your destination. But, during suspend, or during resume, randomly the bug triggers leaving you with no choice but a hardware reset. Ultimately, resulting in you losing the entire work state you were in.

I very recently met someone, and we had a good productive discussion on the features and (long standing) bugs of the Linux kernel. No doubt, Linux is the most featureful kernel in the market. Is also a lot appealing given its breadth of platform support.

Of that discussion we had, it led about Linux’s behavior in tighter stressed scenarios where there is a lot of contention among the core subsystems. From the conversation, I got the feedback that perhaps the issue is no more valid. My conclusion was I must have missed out on the fix because I haven’t really spent any Engineering Lab time in recent past.

We are almost at the end of 2014. While 2014 has been a year with many mixed experiences, I think it does warrant one blog entry ;-)

Recently, I’ve again started spending more time on Linux products / solutions, than spending time focused on a specfic subsystem. This change has been good. It has allowed me to re-cap all the advancements that have happened in the Linux world, umm… in the last 5 years.

The power consumption on the Linux kernel 3.10 is pretty bad.

On kernel 3.10, with the follwing config, the PowerTop results are:

#

# Timers subsystem

#

CONFIG_TICK_ONESHOT=y

CONFIG_NO_HZ_COMMON=y

# CONFIG_HZ_PERIODIC is not set

CONFIG_NO_HZ_IDLE=y

# CONFIG_NO_HZ_FULL is not set

CONFIG_NO_HZ=y

CONFIG_HIGH_RES_TIMERS=y

PowerTOP v2.0 Overview Idle stats Frequency stats Device stats Tunables

The battery reports a discharge rate of 28.0 W

The estimated remaining time is 23 minutes

Summary: 1785.5 wakeups/second, 0.0 GPU ops/second, 0.0 VFS ops/sec and 22.1% CPU use