Dotaz: BUG: soft lockup - CPU#1 stuck

[lertimir]

Potkali jste někdy takovou chybu?

Message from syslogd@dnopytle at Mar  5 00:03:08 ...
 kernel:[713360.730106] BUG: soft lockup - CPU#1 stuck for 22s! [vlc:25552]

VLC pri pokusu o posun v jednom videu se pověsil. Grafické prostředí nereaguje. přechod na konzoli CTRL-ALT-F1 nereaguje. nicméně jde se do systému lognout zvně na ssh. Ale ani tím si moc nepomohu. VLC nejde killnout killall -9 vlc a nabíhají na všech terminálech výše uvedené hlášky. dost možná odstartovaly po pokusu jej kilnout. Dokonce nefunguje ps -ef. Po nějakém vypsání řádků asi narazí na informaci o procesu s vlc a výpis se zastaví a ps nejde zastavit (dokonce ani tak, že se lognu v jiném ssh na roota a pokusím se ho kilnout.)

---

---

Odpovědi

[lertimir]

A tohle se při chybě nahodí do /var/log/messages

2015-03-05T00:21:08.582373+01:00 dnopytle kernel: [714440.705246] BUG: soft lockup - CPU#1 stuck for 22s! [vlc:25552]
2015-03-05T00:21:08.582388+01:00 dnopytle kernel: [714440.705249] Modules linked in: udf vboxpci(O) vboxnetadp(O) vboxnetflt(O) vboxdrv(O) nls_utf8 isofs sr_mod cdrom uas usb_storage bnep bluetooth 6lowpan_iphc rfkill btrfs xor raid6_pq dm_crypt algif_skcipher af_alg xt_pkttype xt_LOG xt_limit rpcsec_gss_krb5 auth_rpcgss oid_registry nfsv4 dns_resolver nfs lockd sunrpc fscache iscsi_ibft iscsi_boot_sysfs af_packet ip6t_REJECT xt_tcpudp nf_conntrack_ipv6 nf_defrag_ipv6 ip6table_raw ipt_REJECT iptable_raw xt_CT iptable_filter ip6table_mangle nf_conntrack_netbios_ns nf_conntrack_broadcast nf_conntrack_ipv4 nf_defrag_ipv4 ip_tables xt_conntrack nf_conntrack ip6table_filter ip6_tables x_tables r8169 iTCO_wdt mii iTCO_vendor_support gpio_ich xfs libcrc32c fuse joydev mxm_wmi snd_virtuoso snd_oxygen_lib snd_mpu401_uart snd_rawmidi snd_pcm snd_seq x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel aesni_intel aes_x86_64 lrw gf128mul glue_helper ablk_helper cryptd snd_seq_device snd_timer pcspkr serio_raw i2c_i801 snd soundcore lpc_ich mfd_core shpchp mei_me mei tpm_infineon tpm_tis tpm wmi processor firewire_ohci firewire_core crc_itu_t i915 i2c_algo_bit video drm_kms_helper xhci_hcd drm button dm_mirror dm_region_hash dm_log dm_mod sg [last unloaded: vboxdrv]
2015-03-05T00:21:08.582389+01:00 dnopytle kernel: [714440.705306] CPU: 1 PID: 25552 Comm: vlc Tainted: G      D W  O  3.16.7-7-desktop #1
2015-03-05T00:21:08.582390+01:00 dnopytle kernel: [714440.705307] Hardware name: Gigabyte Technology Co., Ltd. Z68X-UD3H-B3/Z68X-UD3H-B3, BIOS F8 07/26/2011
2015-03-05T00:21:08.582390+01:00 dnopytle kernel: [714440.705308] task: ffff88002044c290 ti: ffff88014b898000 task.ti: ffff88014b898000
2015-03-05T00:21:08.582391+01:00 dnopytle kernel: [714440.705309] RIP: 0010:[<ffffffff81622440>]  [<ffffffff81622440>] _raw_spin_lock+0x30/0x40
2015-03-05T00:21:08.582398+01:00 dnopytle kernel: [714440.705315] RSP: 0018:ffff88014b89bd78  EFLAGS: 00000297
2015-03-05T00:21:08.582399+01:00 dnopytle kernel: [714440.705315] RAX: 0000000000000000 RBX: ffff880036c07d28 RCX: 0000000000000001
2015-03-05T00:21:08.582399+01:00 dnopytle kernel: [714440.705316] RDX: 0000000000000001 RSI: 0000000000000086 RDI: ffff88002752c5c0
2015-03-05T00:21:08.582400+01:00 dnopytle kernel: [714440.705317] RBP: ffff88002752c5c0 R08: ffff88014b89bb68 R09: 0000000000000000
2015-03-05T00:21:08.582400+01:00 dnopytle kernel: [714440.705318] R10: 0000000000000000 R11: 00000000ffffffff R12: 0000000000000086
2015-03-05T00:21:08.582400+01:00 dnopytle kernel: [714440.705319] R13: ffffffff81069fb7 R14: 0000000000000086 R15: ffff880036c07d48
2015-03-05T00:21:08.582401+01:00 dnopytle kernel: [714440.705320] FS:  00007f444373b700(0000) GS:ffff88021fa40000(0000) knlGS:0000000000000000
2015-03-05T00:21:08.582401+01:00 dnopytle kernel: [714440.705321] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
2015-03-05T00:21:08.582402+01:00 dnopytle kernel: [714440.705321] CR2: 00007f447bec7000 CR3: 0000000039c94000 CR4: 00000000000407e0
2015-03-05T00:21:08.582402+01:00 dnopytle kernel: [714440.705322] Stack:
2015-03-05T00:21:08.582402+01:00 dnopytle kernel: [714440.705323]  ffffffffa012da85 0000000000000246 ffff88014a454ac0 ffff88014b89be28
2015-03-05T00:21:08.582403+01:00 dnopytle kernel: [714440.705325]  ffff88003fb1fa00 00000000fffffff4 ffff88003fb1fa00 00000000fffffff2
2015-03-05T00:21:08.582403+01:00 dnopytle kernel: [714440.705326]  ffffffffa012e4cc 0000000000000063 ffff88014b89be28 0000000000000073
2015-03-05T00:21:08.582404+01:00 dnopytle kernel: [714440.705328] Call Trace:
2015-03-05T00:21:08.582404+01:00 dnopytle kernel: [714440.705345]  [<ffffffffa012da85>] i915_gem_userptr_init__mmu_notifier+0x295/0x3c0 [i915]
2015-03-05T00:21:08.582405+01:00 dnopytle kernel: [714440.705376]  [<ffffffffa012e4cc>] i915_gem_userptr_ioctl+0x12c/0x1e0 [i915]
2015-03-05T00:21:08.582405+01:00 dnopytle kernel: [714440.705403]  [<ffffffffa004d8c7>] drm_ioctl+0x1c7/0x5b0 [drm]
2015-03-05T00:21:08.582405+01:00 dnopytle kernel: [714440.705409]  [<ffffffff811cad17>] do_vfs_ioctl+0x2e7/0x4c0
2015-03-05T00:21:08.582406+01:00 dnopytle kernel: [714440.705414]  [<ffffffff811caf71>] SyS_ioctl+0x81/0xa0
2015-03-05T00:21:08.582406+01:00 dnopytle kernel: [714440.705417]  [<ffffffff81622a2d>] system_call_fastpath+0x1a/0x1f
2015-03-05T00:21:08.582407+01:00 dnopytle kernel: [714440.705419]  [<00007f4486255c07>] 0x7f4486255c06
2015-03-05T00:21:08.582407+01:00 dnopytle kernel: [714440.705420] Code: 65 ff 04 25 60 a9 00 00 b8 00 00 01 00 f0 0f c1 07 89 c2 c1 ea 10 66 39 c2 89 d1 75 01 c3 0f b7 07 66 39 d0 74 f7 f3 90 0f b7 07 <66> 39 c8 75 f6 c3 66 2e 0f 1f 84 00 00 00 00 00 66 66 66 66 90 

Vypnu to. Ale zajímá mne, co by to mohlo být, že klientská aplikace takto něco pošle do jádra.

[Martin]

Off topic: Pise to v logu, dosahnul jste dno pytle v kernelu.

[Peter Golis]

Vbox, jeho verzia asi nie je posledná a počet fyzických CPU nie je menší ako počet CPU pridelený tej virtuálke, a tak isto niesú rozdielne verzie komponentov virtual boxu medzi host a guest.

[lertimir]

žádná virtualizace neběžela. jen byly nataženy kernelí moduly pro vbox (automatické natahování kernelích modulů si instalace udělá sama)

[michich]

Soft lockup znamená, že příslušný procesor (zde CPU1) je v jádře déle než daný limit (~20 sekund), což v praxi znamená, že je buď systém brutálně přetížený nebo je někde chyba, která způsobila, že se z toho jádra (nejspíš nikdy) nevrátí. V tomto případě to vypadá, že i915_gem_userptr_init__mmu_notifier() čeká na nějaký spinlock a nejspíš se ho nikdy nedočká.

Co se týká řešení, pokud nebudete mít štěstí a nenarazíte na odpovídající opravu v changelogu, obávám se, že to bude chtít někoho, kdo se v téhle části jádra vyzná. Navíc z logu zjistíte nanejvýš to, který spinlock to je a kde v té funkci ho zkouší zamknout, ale ne kdo ho drží a proč. Na to by byl potřeba přinejmenším stack trace všech procesů (Alt-SysRq-T), ideálně pak kompletní crash dump.

Pokud se to stalo jen jednou a nemáte vysloveně chuť se do toho ponořit, asi bych se na to vykašlal.

[lertimir]

Díky za vysvětlení. Řešit to nebudu, hlavně díky času, možná později, až čas mít budu. Stalo se to jednou za dobu provozu, na druhou stranu chybu jsem vyvolal opakovaně. Zavolání vlc na stejněm avi a provedení podobného posuvu systém opět pověsilo. Běžel v té chvili, firefox, krusade, několik pohledů s Dolphinem a balík KDE utilit. V prvním případě měla v době chyby uptime několik dní a asi hodinu nebo dvě předtím jsem restartoval firefox, protože nabral asi 5GB ram a asi 3GB odložil do swapu. V druhém případě to byl v podstatě čerstvý reboot a najetí KDE.

Spíše je zajímavá otázka, jak může obyčejná grafická aplikace takto nabořit jádro? Myslel jsem, že separace základního běhu systému je silnější.

[MadCatX]

Nejde o to, že by VLC nabořilo jádro, ale o bug v jaderném kódu, který VLC nějakou operací vyvolá. Ten konkrétní kód dle backtrace pracuje s userptr (kus paměti naalokované userspacem se předá do jádra, aniž by se cokoliv někam kopírovalo) a v jádře je to až od verze 3.16, takže to nemusí být úplně odladěné. Předpokládám, že máte ve VLC zapnutou akceleraci přes VAAPI? Pokud ano, možná by bylo zajímavé zkusit, zda se to stane i bez zapnuté HW akcelerace.

Pokud je to video publikovatelné a problém se dá spolehlivě reprodukovat, asi bych to hlásil jako bug.

[lertimir]

OK. mám openSUSE 13.2, kde je právě jádro 3.16

[luky]

Nejedna se o prvni chybu v kernelu - "Tainted: D" ! Chyba muze byt zavlecena a zpusobena predchozim OOPSem. Doporucuji se nejprve zabyvat tim prvnim problemem.

[Michal Kubeček]

Obecně máte pravdu, ale v tomto případě to klidně může znamenat jen to, že ten soft lockup už nějakou dobu trvá. Viz též úvodní post, kde je tatáž hláška s timestampem 713360.730106 (tj. asi o 18 minut dříve).

[vasek]

Zkusil bych odebrat nahrané virtualbox moduly a nahrát je pouze tehdy, až budou potřeba. Už mnohokrát jsem měl problémy s virtualboxem dohromady s intelí grafikou. Vlastně si ani nepamatuji verzi virtualboxu, ve které bych nenarazil na nějaké viditelné problémy (i pod widlous) - nová verze chyby opraví a přinese vždy nové ...