auron_paine, lulu, samus, auron_yuna: Timeout in intel_crtc_wait_for_pending_flips() when restarting/stopping chrome |
||||||||||||||
Issue descriptionChrome Version: 62.0.3176.0 OS: Chrome OS 9841.0.0 What steps will reproduce the problem? (1) HWTest [bvt-inline] seems to trigger this in cheets_StartAndroid.stress What is the expected result? No timeout, chrome restarts fine and the test passes. What happens instead? There is a timeout in the i915 driver, chrome takes much longer to start (> 60s.) and the test fails. Please use labels and text to provide additional information. Example builds on which the problem happened: https://luci-milo.appspot.com/buildbot/chromeos/auron_paine-release/1399 https://luci-milo.appspot.com/buildbot/chromeos/lulu-release/1402 For graphics-related bugs, please copy/paste the contents of the about:gpu page at the end of this report. Here existing instance is being stopped: 2017-08-14T21:31:31.454556+00:00 INFO session_manager[24458]: [INFO:browser_job.cc(157)] Terminating process: 2017-08-14T21:31:31.454572+00:00 INFO session_manager[24458]: [INFO:system_utils_impl.cc(111)] Sending 15 to 24530 as 1000 2017-08-14T21:31:31.454599+00:00 INFO session_manager[24458]: [INFO:system_utils_impl.cc(111)] Sending 15 to 24781 as 1000 2017-08-14T21:31:31.788954+00:00 INFO kernel: [ 527.320273] binder: release 25262:25262 transaction 474517 out, still active 2017-08-14T21:31:31.788968+00:00 INFO kernel: [ 527.320289] binder: release 25262:25262 transaction 474501 in, still active 2017-08-14T21:31:31.843950+00:00 INFO kernel: [ 527.375328] binder: release 25261:25261 transaction 474517 in, still active 2017-08-14T21:31:31.843970+00:00 INFO kernel: [ 527.375342] binder: send failed reply for transaction 474517, target dead 2017-08-14T21:31:31.843972+00:00 INFO kernel: [ 527.375353] binder: send failed reply for transaction 474501 to 26127:26646 Note the timestamp: 21:31:31 2017-08-14T21:31:51.476946+00:00 WARNING kernel: [ 547.000812] init: ui main process (24458) killed by KILL signal 2017-08-14T21:31:51.545359+00:00 INFO chapsd[1139]: Token at /home/root/2a002191fa3837ecbdabbf0aed9003a6b404a213/chaps has been removed from slot 1 2017-08-14T21:31:51.575137+00:00 INFO chapsd[1139]: Unloaded keys for slot 1 2017-08-14T21:31:51.575924+00:00 INFO kernel: [ 547.099731] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x0 2017-08-14T21:31:51.700976+00:00 CRIT ui-post-stop-unkillable[27395]: 24617 D< [chrome] 2017-08-14T21:31:51.701143+00:00 CRIT ui-post-stop-unkillable[27395]: 24623 Z< [chrome] <defunct> 2017-08-14T21:31:53.990985+00:00 ERR cryptohomed[1411]: We ended up invalidating key 352159884 2017-08-14T21:31:54.009651+00:00 WARNING chapsd[1139]: Unload Token event received for unknown path: /home/root/2a002191fa3837ecbdabbf0aed9003a6b404a213/chaps 2017-08-14T21:31:54.061275+00:00 ERR imageloader[27414]: Failed to read latest-version file. 2017-08-14T21:31:54.061297+00:00 ERR imageloader[27414]: Failed to verify and mount component. 2017-08-14T21:31:54.071949+00:00 WARNING kernel: [ 549.595380] init: imageloader main process (27414) terminated with status 1 2017-08-14T21:31:54.197069+00:00 INFO session_manager[27517]: [INFO:session_manager_main.cc(195)] Will wait 3s for graceful browser exit. 2017-08-14T21:31:54.203874+00:00 INFO session_manager[27517]: [INFO:session_manager_service.cc(140)] SessionManagerService starting 2017-08-14T21:31:54.208747+00:00 INFO session_manager[27517]: [INFO:browser_job.cc(140)] Running child /opt/google/chrome/chrome --ppapi-flash-path=/opt/google/chrome/pepper/libpepflashplayer.so --ppapi-flash-version=26.0.0.137 --ui-prioritize-in-gpu-process --use-gl=egl --enable-native-gpu-memory-buffers --gpu-sandbox-failures-fatal=yes --enable-logging --log-level=1 --use-cras --enable-wayland-server --user-data-dir=/home/chronos --max-unused-resource-memory-usage-percentage=5 --system-developer-mode --login-profile=user --has-chromeos-keyboard --default-wallpaper-large=/usr/share/chromeos-assets/wallpaper/oem_large.jpg --default-wallpaper-small=/usr/share/chromeos-assets/wallpaper/oem_small.jpg --default-wallpaper-is-oem --guest-wallpaper-large=/usr/share/chromeos-assets/wallpaper/guest_large.jpg --guest-wallpaper-small=/usr/share/chromeos-assets/wallpaper/guest_small.jpg --enable-consumer-kiosk --arc-availability=officially-supported --enterprise-enrollment-initial-modulus=15 --enterprise-enrollment-modulus-limit=19 --login-manager --vmodule=*arc/*=1,tablet_power_button_controller=1,*chromeos/login/*=1,auto_enrollment_controller=1,*plugin*=2,*zygote*=1,*/ui/ozone/*=1,*/ui/display/manager/chromeos/*=1,power_button_observer=2,webui_login_view=2,lock_state_controller=2,webui_screen_locker=2,screen_locker=2 2017-08-14T21:31:54.331922+00:00 DEBUG kernel: [ 549.855377] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs 2017-08-14T21:31:54.363618+00:00 INFO session_manager[27517]: [INFO:child_exit_handler.cc(77)] Handling 27534 exit. 2017-08-14T21:31:54.369934+00:00 DEBUG kernel: [ 549.892884] SELinux: initialized (dev proc, type proc), uses genfs_contexts 2017-08-14T21:31:54.580879+00:00 INFO session_manager[27517]: [INFO:browser_job.cc(157)] Terminating process: 2017-08-14T21:31:54.580900+00:00 INFO session_manager[27517]: [INFO:system_utils_impl.cc(111)] Sending 15 to 27535 as 1000 2017-08-14T21:31:54.676001+00:00 DEBUG kernel: [ 550.198848] SELinux: initialized (dev proc, type proc), uses genfs_contexts 2017-08-14T21:31:54.690930+00:00 DEBUG kernel: [ 550.214026] SELinux: initialized (dev proc, type proc), uses genfs_contexts 2017-08-14T21:31:54.748515+00:00 INFO session_manager[27517]: [INFO:session_manager_service.cc(464)] SessionManagerService quitting run loop 2017-08-14T21:31:54.749147+00:00 INFO session_manager[27517]: [INFO:session_manager_service.cc(206)] SessionManagerService exiting 2017-08-14T21:31:54.894544+00:00 CRIT ui-post-stop-unkillable[27822]: 24617 D< [chrome] 2017-08-14T21:31:54.894708+00:00 CRIT ui-post-stop-unkillable[27822]: 24623 Z< [chrome] <defunct> 2017-08-14T21:31:55.080234+00:00 ERR imageloader[27848]: Failed to read latest-version file. 2017-08-14T21:31:55.080256+00:00 ERR imageloader[27848]: Failed to verify and mount component. 2017-08-14T21:31:55.087928+00:00 WARNING kernel: [ 550.610675] init: imageloader main process (27848) terminated with status 1 2017-08-14T21:31:55.200850+00:00 WARNING session_manager[27951]: [WARNING:libpolicy.cc(36)] Could not load the device policy file. 2017-08-14T21:31:55.201235+00:00 INFO session_manager[27951]: [INFO:session_manager_main.cc(195)] Will wait 3s for graceful browser exit. 2017-08-14T21:31:55.206162+00:00 INFO session_manager[27951]: [INFO:session_manager_service.cc(140)] SessionManagerService starting 2017-08-14T21:31:55.207696+00:00 INFO session_manager[27951]: [INFO:policy_key.cc(53)] No policy key on disk at /var/lib/whitelist/owner.key 2017-08-14T21:31:55.210056+00:00 INFO session_manager[27951]: [INFO:browser_job.cc(140)] Running child /opt/google/chrome/chrome --ppapi-flash-path=/opt/google/chrome/pepper/libpepflashplayer.so --ppapi-flash-version=26.0.0.137 --ui-prioritize-in-gpu-process --use-gl=egl --enable-native-gpu-memory-buffers --gpu-sandbox-failures-fatal=yes --enable-logging --log-level=1 --use-cras --enable-wayland-server --user-data-dir=/home/chronos --max-unused-resource-memory-usage-percentage=5 --system-developer-mode --login-profile=user --has-chromeos-keyboard --default-wallpaper-large=/usr/share/chromeos-assets/wallpaper/oem_large.jpg --default-wallpaper-small=/usr/share/chromeos-assets/wallpaper/oem_small.jpg --default-wallpaper-is-oem --guest-wallpaper-large=/usr/share/chromeos-assets/wallpaper/guest_large.jpg --guest-wallpaper-small=/usr/share/chromeos-assets/wallpaper/guest_small.jpg --enable-consumer-kiosk --arc-availability=officially-supported --enterprise-enrollment-initial-modulus=15 --enterprise-enrollment-modulus-limit=19 --login-manager --vmodule=*arc/*=1,tablet_power_button_controller=1,*chromeos/login/*=1,auto_enrollment_controller=1,*plugin*=2,*zygote*=1,*/ui/ozone/*=1,*/ui/display/manager/chromeos/*=1,power_button_observer=2,webui_login_view=2,lock_state_controller=2,webui_screen_locker=2,screen_locker=2 2017-08-14T21:31:55.288960+00:00 DEBUG kernel: [ 550.811492] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs 2017-08-14T21:31:55.378927+00:00 DEBUG kernel: [ 550.901411] SELinux: initialized (dev proc, type proc), uses genfs_contexts 2017-08-14T21:31:55.669940+00:00 DEBUG kernel: [ 551.192403] SELinux: initialized (dev proc, type proc), uses genfs_contexts 2017-08-14T21:31:55.681933+00:00 DEBUG kernel: [ 551.204482] SELinux: initialized (dev proc, type proc), uses genfs_contexts 2017-08-14T21:31:55.696579+00:00 INFO session_manager[27951]: [INFO:browser_job.cc(149)] Terminating process group: Restarting browser on-demand. 2017-08-14T21:31:55.696650+00:00 INFO session_manager[27951]: [INFO:system_utils_impl.cc(111)] Sending 9 to -27966 as 1000 2017-08-14T21:32:13.504678+00:00 NOTICE autotest[28120]: 14:32:13.498 ERROR| browser:0068| Failed with TimeoutException while starting the browser backend. 2017-08-14T21:32:13.601018+00:00 INFO session_manager[27951]: [INFO:browser_job.cc(157)] Terminating process: 2017-08-14T21:32:13.601041+00:00 INFO session_manager[27951]: [INFO:system_utils_impl.cc(111)] Sending 15 to 27966 as 1000 2017-08-14T21:32:31.657045+00:00 WARNING kernel: [ 587.166309] ------------[ cut here ]------------ 2017-08-14T21:32:31.657070+00:00 WARNING kernel: [ 587.166338] WARNING: CPU: 1 PID: 24617 at /mnt/host/source/src/third_party/kernel/v3.14/drivers/gpu/drm/i915/intel_display.c:3090 intel_crtc_wait_for_pending_flips+0xec/0x1b9() 2017-08-14T21:32:31.657073+00:00 NOTICE kernel: [ 587.166369] Modules linked in: ip6t_REJECT xt_TCPMSS ip6table_mangle ip6table_raw veth uinput i2c_dev zram memc_x86 cmac x86_pkg_temp_thermal iwlmvm xt_nat snd_hda_codec_realtek snd_hda_codec_generic cros_ec_accel iio_trig_sysfs kfifo_buf industrialio snd_hda_codec_hdmi iwlwifi smsc75xx iwl7000_mac80211 snd_hda_intel snd_hda_controller snd_hda_codec snd_hwdep bridge stp llc snd_soc_sst_acpi rfcomm ipt_MASQUERADE iptable_nat nf_nat_ipv4 nf_nat xt_mark fuse cfg80211 ip6table_filter snd_seq_midi ip6_tables snd_seq_midi_event snd_rawmidi snd_seq snd_seq_device smsc95xx usbnet mii btusb btbcm btintel bluetooth uvcvideo videobuf2_vmalloc joydev 2017-08-14T21:32:31.657075+00:00 NOTICE kernel: [ 587.166604] CPU: 1 PID: 24617 Comm: chrome Tainted: G W 3.14.0 #1 2017-08-14T21:32:31.657078+00:00 NOTICE kernel: [ 587.166619] Hardware name: GOOGLE Lulu, BIOS Google_Lulu.6301.136.57 03/28/2016 2017-08-14T21:32:31.657079+00:00 NOTICE kernel: [ 587.166635] 0000000000000000 00000000eafb215b ffff88006bf498f0 ffffffffae41b31c 2017-08-14T21:32:31.657081+00:00 NOTICE kernel: [ 587.166659] 0000000000000000 ffff88006bf49928 ffffffffade5d7e8 ffffffffae158a65 2017-08-14T21:32:31.657083+00:00 NOTICE kernel: [ 587.166681] ffff880077da5000 ffff8800785fea08 ffff8800785fe800 ffff880077df2f48 2017-08-14T21:32:31.657085+00:00 NOTICE kernel: [ 587.166704] Call Trace: 2017-08-14T21:32:31.657086+00:00 NOTICE kernel: [ 587.166720] [<ffffffffae41b31c>] dump_stack+0x4d/0x6f 2017-08-14T21:32:31.657088+00:00 NOTICE kernel: [ 587.166737] [<ffffffffade5d7e8>] warn_slowpath_common+0x7f/0x98 2017-08-14T21:32:31.657090+00:00 NOTICE kernel: [ 587.166755] [<ffffffffae158a65>] ? intel_crtc_wait_for_pending_flips+0xec/0x1b9 2017-08-14T21:32:31.657092+00:00 NOTICE kernel: [ 587.166774] [<ffffffffade5d8fa>] warn_slowpath_null+0x1a/0x1c 2017-08-14T21:32:31.657094+00:00 NOTICE kernel: [ 587.166791] [<ffffffffae158a65>] intel_crtc_wait_for_pending_flips+0xec/0x1b9 2017-08-14T21:32:31.657096+00:00 NOTICE kernel: [ 587.166811] [<ffffffffade957bc>] ? finish_wait+0x62/0x62 2017-08-14T21:32:31.657097+00:00 NOTICE kernel: [ 587.166828] [<ffffffffae15f35d>] haswell_crtc_disable+0x49/0x293 2017-08-14T21:32:31.657099+00:00 NOTICE kernel: [ 587.166846] [<ffffffffae16038b>] __intel_set_mode+0x98b/0x121e 2017-08-14T21:32:31.657101+00:00 NOTICE kernel: [ 587.166865] [<ffffffffadf38a6c>] ? __slab_free+0x23b/0x3c0 2017-08-14T21:32:31.657103+00:00 NOTICE kernel: [ 587.166882] [<ffffffffae162d72>] intel_set_mode+0x14/0x2a 2017-08-14T21:32:31.657104+00:00 NOTICE kernel: [ 587.166933] [<ffffffffae163733>] intel_crtc_set_config+0x8a7/0x965 2017-08-14T21:32:31.657106+00:00 NOTICE kernel: [ 587.166953] [<ffffffffae121f0f>] drm_mode_set_config_internal+0x5b/0xe5 2017-08-14T21:32:31.657108+00:00 NOTICE kernel: [ 587.166972] [<ffffffffae1223e1>] drm_framebuffer_remove+0x185/0x230 2017-08-14T21:32:31.657110+00:00 NOTICE kernel: [ 587.166989] [<ffffffffae125b13>] drm_fb_release+0xa9/0xc9 2017-08-14T21:32:31.657111+00:00 NOTICE kernel: [ 587.167007] [<ffffffffae117ce7>] drm_release+0x28b/0x50b 2017-08-14T21:32:31.657113+00:00 NOTICE kernel: [ 587.167023] [<ffffffffadf493df>] __fput+0xe1/0x19a 2017-08-14T21:32:31.657115+00:00 NOTICE kernel: [ 587.167038] [<ffffffffadf494ce>] ____fput+0xe/0x10 2017-08-14T21:32:31.657117+00:00 NOTICE kernel: [ 587.167054] [<ffffffffade78a17>] task_work_run+0x7d/0x93 2017-08-14T21:32:31.657118+00:00 NOTICE kernel: [ 587.167070] [<ffffffffade5fad2>] do_exit+0x40d/0x94d 2017-08-14T21:32:31.657120+00:00 NOTICE kernel: [ 587.167088] [<ffffffffade6aa61>] ? __dequeue_signal+0x1a/0x136 2017-08-14T21:32:31.657122+00:00 NOTICE kernel: [ 587.167105] [<ffffffffade6008a>] do_group_exit+0x42/0xb0 2017-08-14T21:32:31.657124+00:00 NOTICE kernel: [ 587.167120] [<ffffffffade6d79b>] get_signal_to_deliver+0x567/0x58d 2017-08-14T21:32:31.657125+00:00 NOTICE kernel: [ 587.167138] [<ffffffffade01eb3>] do_signal+0x57/0x527 2017-08-14T21:32:31.657127+00:00 NOTICE kernel: [ 587.167156] [<ffffffffadeb5b90>] ? do_futex+0xc0/0x7f1 2017-08-14T21:32:31.657129+00:00 NOTICE kernel: [ 587.167173] [<ffffffffaded5584>] ? __secure_computing+0xd7/0x2fa 2017-08-14T21:32:31.657130+00:00 NOTICE kernel: [ 587.167208] [<ffffffffade023ac>] do_notify_resume+0x29/0x5b 2017-08-14T21:32:31.657132+00:00 NOTICE kernel: [ 587.167224] [<ffffffffae423d6e>] int_signal+0x12/0x17 2017-08-14T21:32:31.657134+00:00 WARNING kernel: [ 587.167238] ---[ end trace 819bf54d4f17aa77 ]--- Here is the kernel timeout. Compare the timestamp (21:32:31) to the timestamp of when chrome started stopping (21:31:31). This, and also the backtrace (DRM calls happening from do_exit), strongly suggests that the timeout delays termination of chrome. 2017-08-14T21:32:31.929376+00:00 INFO session_manager[27951]: [INFO:session_manager_service.cc(464)] SessionManagerService quitting run loop 2017-08-14T21:32:31.929459+00:00 INFO session_manager[27951]: [INFO:session_manager_service.cc(206)] SessionManagerService exiting 2017-08-14T21:32:31.994124+00:00 INFO kernel: [ 587.503379] br0: port 1(veth_android) entered disabled state 2017-08-14T21:32:31.994140+00:00 INFO kernel: [ 587.503826] device veth_android left promiscuous mode 2017-08-14T21:32:31.994141+00:00 INFO kernel: [ 587.503844] br0: port 1(veth_android) entered disabled state 2017-08-14T21:32:32.299567+00:00 ERR imageloader[28196]: Failed to read latest-version file. 2017-08-14T21:32:32.299604+00:00 ERR imageloader[28196]: Failed to verify and mount component. 2017-08-14T21:32:32.309991+00:00 WARNING kernel: [ 587.819540] init: imageloader main process (28196) terminated with status 1 2017-08-14T21:32:32.360029+00:00 WARNING session_manager[28300]: [WARNING:libpolicy.cc(36)] Could not load the device policy file. 2017-08-14T21:32:32.360385+00:00 INFO session_manager[28300]: [INFO:session_manager_main.cc(195)] Will wait 3s for graceful browser exit. 2017-08-14T21:32:32.363951+00:00 INFO session_manager[28300]: [INFO:session_manager_service.cc(140)] SessionManagerService starting 2017-08-14T21:32:32.365455+00:00 INFO session_manager[28300]: [INFO:policy_key.cc(53)] No policy key on disk at /var/lib/whitelist/owner.key 2017-08-14T21:32:32.367555+00:00 INFO session_manager[28300]: [INFO:browser_job.cc(140)] Running child /opt/google/chrome/chrome --ppapi-flash-path=/opt/google/chrome/pepper/libpepflashplayer.so --ppapi-flash-version=26.0.0.137 --ui-prioritize-in-gpu-process --use-gl=egl --enable-native-gpu-memory-buffers --gpu-sandbox-failures-fatal=yes --enable-logging --log-level=1 --use-cras --enable-wayland-server --user-data-dir=/home/chronos --max-unused-resource-memory-usage-percentage=5 --system-developer-mode --login-profile=user --has-chromeos-keyboard --default-wallpaper-large=/usr/share/chromeos-assets/wallpaper/oem_large.jpg --default-wallpaper-small=/usr/share/chromeos-assets/wallpaper/oem_small.jpg --default-wallpaper-is-oem --guest-wallpaper-large=/usr/share/chromeos-assets/wallpaper/guest_large.jpg --guest-wallpaper-small=/usr/share/chromeos-assets/wallpaper/guest_small.jpg --enable-consumer-kiosk --arc-availability=officially-supported --enterprise-enrollment-initial-modulus=15 --enterprise-enrollment-modulus-limit=19 --login-manager -- Here the new instance is finally started.
,
Aug 15 2017
It looks like the same problem is affecting samus, although it manifests in different tests. Example build: https://luci-milo.appspot.com/buildbot/chromeos/samus-release/4572 Looking at /var/log/messages (https://storage.cloud.google.com/chromeos-autotest-results/135100057-chromeos-test/chromeos2-row3-rack11-host5/sysinfo/var/log/messages?_ga=2.136356855.-672223342.1502780285), it seems like autoupdate wants to restart chrome, but it times out. 2017-08-14T20:28:38.481222-07:00 INFO session_manager[10590]: [INFO:session_manager_impl.cc(428)] emitting D-Bus signal SessionStateChanged:stopping 2017-08-14T20:28:38.481407-07:00 INFO session_manager[10590]: [INFO:browser_job.cc(157)] Terminating process: 2017-08-14T20:28:38.481439-07:00 INFO session_manager[10590]: [INFO:system_utils_impl.cc(111)] Sending 15 to 10656 as 1000 2017-08-14T20:28:38.481508-07:00 INFO session_manager[10590]: [INFO:system_utils_impl.cc(111)] Sending 15 to 10862 as 1000 Waiting for chrome to terminate voluntarily. 2017-08-14T20:28:57.600091-07:00 WARNING kernel: [ 387.383535] init: ui main process (10590) killed by KILL signal 2017-08-14T20:28:57.644473-07:00 INFO chapsd[1514]: Token at /home/root/cd4af4fb4669f9b5c152b25b3b747e1244321a5a/chaps has been removed from slot 1 2017-08-14T20:28:57.674206-07:00 INFO chapsd[1514]: Unloaded keys for slot 1 2017-08-14T20:28:57.675048-07:00 INFO kernel: [ 387.458174] tpm_tis tpm_tis: command 0xba (size 18) returned code 0x0 2017-08-14T20:28:57.717586-07:00 CRIT ui-post-stop-unkillable[14260]: 10697 Z<l [chrome] <defunct> 2017-08-14T20:28:57.717611-07:00 CRIT ui-post-stop-unkillable[14260]: 10701 D< [chrome] It didn't, so we sent kill, but it still remained stuck (uninterruptible sleep in the kernel). 2017-08-14T20:29:00.084753-07:00 ERR cryptohomed[2947]: We ended up invalidating key 131592240 2017-08-14T20:29:00.105105-07:00 WARNING chapsd[1514]: Unload Token event received for unknown path: /home/root/cd4af4fb4669f9b5c152b25b3b747e1244321a5a/chaps 2017-08-14T20:29:00.160422-07:00 ERR imageloader[14281]: Failed to read latest-version file. 2017-08-14T20:29:00.160443-07:00 ERR imageloader[14281]: Failed to verify and mount component. 2017-08-14T20:29:00.176103-07:00 WARNING kernel: [ 389.961445] init: imageloader main process (14281) terminated with status 1 2017-08-14T20:29:00.246564-07:00 WARNING session_manager[14444]: [WARNING:chrome_setup.cc(86)] Could not find both paths: /usr/share/chromeos-assets/wallpaper/oem_large.jpg and /usr/share/chromeos-assets/wallpaper/oem_small.jpg 2017-08-14T20:29:00.247145-07:00 INFO session_manager[14444]: [INFO:session_manager_main.cc(195)] Will wait 3s for graceful browser exit. 2017-08-14T20:29:00.249078-07:00 INFO session_manager[14444]: [INFO:session_manager_service.cc(140)] SessionManagerService starting 2017-08-14T20:29:00.253237-07:00 INFO session_manager[14444]: [INFO:browser_job.cc(140)] Running child /opt/google/chrome/chrome --ppapi-flash-path=/opt/google/chrome/pepper/libpepflashplayer.so --ppapi-flash-version=26.0.0.137 --ui-prioritize-in-gpu-process --use-gl=egl --enable-native-gpu-memory-buffers --gpu-sandbox-failures-fatal=yes --enable-logging --log-level=1 --use-cras --enable-wayland-server --user-data-dir=/home/chronos --max-unused-resource-memory-usage-percentage=5 --system-developer-mode --login-profile=user --enable-natural-scroll-default --has-chromeos-keyboard --default-wallpaper-large=/usr/share/chromeos-assets/wallpaper/default_large.jpg --default-wallpaper-small=/usr/share/chromeos-assets/wallpaper/default_small.jpg --child-wallpaper-large=/usr/share/chromeos-assets/wallpaper/child_large.jpg --child-wallpaper-small=/usr/share/chromeos-assets/wallpaper/child_small.jpg --guest-wallpaper-large=/usr/share/chromeos-assets/wallpaper/guest_large.jpg --guest-wallpaper-small=/usr/share/chromeos-assets/wallpaper/guest_small.jpg --enable-consumer-kiosk --arc-availability=officially-supported --enterprise-enrollment-initial-modulus=15 --enterprise-enrollment-modulus-limit=19 --login-manager --vmodule=*arc/*=1,tablet_power_button_controller=1,*chromeos/login/*=1,auto_enrollment_controller=1,*plugin*=2,*zygote*=1,*/ui/ozone/*=1,*/ui/display/manager/chromeos/*=1,power_button_observer=2,webui_login_view=2,lock_state_controller=2,webui_screen_locker=2,screen_locker=2 2017-08-14T20:29:00.253795-07:00 INFO session_manager[14444]: [INFO:session_manager_service.cc(217)] Browser is 14471 2017-08-14T20:29:00.296908-07:00 INFO session_manager[14444]: [INFO:child_exit_handler.cc(77)] Handling 14465 exit. 2017-08-14T20:29:00.298132-07:00 DEBUG kernel: [ 390.083401] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs 2017-08-14T20:29:00.457115-07:00 INFO kernel: [ 390.242595] tpm_tis tpm_tis: command 0x65 (size 20) returned code 0x0 2017-08-14T20:29:00.493115-07:00 INFO kernel: [ 390.278568] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0 2017-08-14T20:29:00.499090-07:00 DEBUG kernel: [ 390.284729] SELinux: initialized (dev proc, type proc), uses genfs_contexts 2017-08-14T20:29:00.529089-07:00 INFO kernel: [ 390.314749] tpm_tis tpm_tis: command 0x65 (size 22) returned code 0x0 2017-08-14T20:29:00.559108-07:00 INFO kernel: [ 390.344613] tpm_tis tpm_tis: command 0xba (size 18) returned code 0xc 2017-08-14T20:29:00.583064-07:00 INFO kernel: [ 390.368624] tpm_tis tpm_tis: command 0x15 (size 14) returned code 0x0 2017-08-14T20:29:00.608092-07:00 INFO kernel: [ 390.393851] tpm_tis tpm_tis: command 0x15 (size 14) returned code 0x0 2017-08-14T20:29:00.825088-07:00 DEBUG kernel: [ 390.611310] SELinux: initialized (dev proc, type proc), uses genfs_contexts 2017-08-14T20:29:00.841076-07:00 DEBUG kernel: [ 390.626764] SELinux: initialized (dev proc, type proc), uses genfs_contexts 2017-08-14T20:29:01.104830-07:00 NOTICE ag[14612]: autotest server[stack::ssh_ping|run|wrapper] -> ssh_run(true) 2017-08-14T20:29:02.111892-07:00 NOTICE ag[14617]: autotest server[stack::run_on_client|run|wrapper] -> ssh_run(/usr/local/autotest/result_tools/utils.py -p /usr/local/autotest/results/default ) 2017-08-14T20:29:03.417866-07:00 NOTICE ag[14622]: autotest server[stack::_process_line|run|wrapper] -> ssh_run(echo A > /usr/local/autotest/tmp/_autotmp_1Co0zPharness-fifo/autoserv.fifo) 2017-08-14T20:29:06.374857-07:00 NOTICE ag[14632]: autotest server[stack::ssh_ping|run|wrapper] -> ssh_run(true) 2017-08-14T20:29:06.750502-07:00 NOTICE ag[14634]: autotest server[stack::run_on_client|run|wrapper] -> ssh_run(/usr/local/autotest/result_tools/utils.py -p /usr/local/autotest/results/default ) 2017-08-14T20:29:11.144262-07:00 NOTICE ag[14642]: autotest server[stack::list_files_glob|run|wrapper] -> ssh_run(python -c 'import cPickle, glob, sys;cPickle.dump(glob.glob(sys.argv[1]), sys.stdout, 0)') 2017-08-14T20:29:14.037757-07:00 NOTICE ag[14648]: autotest server[stack::list_files_glob|run|wrapper] -> ssh_run(python -c 'import cPickle, glob, sys;cPickle.dump(glob.glob(sys.argv[1]), sys.stdout, 0)') 2017-08-14T20:29:18.220805-07:00 NOTICE ag[14655]: autotest server[stack::get_network_stats|run|wrapper] -> ssh_run(route; echo SEPARATOR; cat /proc/net/dev) 2017-08-14T20:29:18.924955-07:00 NOTICE ag[14660]: autotest server[stack::close|run|wrapper] -> ssh_run(rm -rf "/tmp/autoserv-no4N5H") 2017-08-14T20:29:18.940600-07:00 INFO sshd[10023]: Received disconnect from 127.0.0.1 port 33710:11: disconnected by user 2017-08-14T20:29:18.940703-07:00 INFO sshd[10023]: Disconnected from 127.0.0.1 port 33710 2017-08-14T20:29:38.563172-07:00 WARNING kernel: [ 428.379544] ------------[ cut here ]------------ 2017-08-14T20:29:38.563202-07:00 WARNING kernel: [ 428.379574] WARNING: CPU: 0 PID: 10712 at /mnt/host/source/src/third_party/kernel/v3.14/drivers/gpu/drm/i915/intel_display.c:3090 intel_crtc_wait_for_pending_flips+0xec/0x1b9() 2017-08-14T20:29:38.563205-07:00 NOTICE kernel: [ 428.379603] Modules linked in: ip6t_REJECT xt_TCPMSS ip6table_mangle ip6table_raw veth rfcomm i2c_dev uinput snd_soc_sst_bdw_rt5677_mach xt_nat snd_soc_sst_haswell_pcm snd_soc_sst_dsp memc_x86 snd_hda_codec_hdmi x86_pkg_temp_thermal bridge stp llc snd_hda_intel snd_soc_rt5677 snd_soc_rl6231 acpi_als industrialio_triggered_buffer snd_soc_sst_acpi zram snd_hda_controller snd_soc_rt5677_spi snd_hda_codec snd_hwdep ipt_MASQUERADE iptable_nat nf_nat_ipv4 nf_nat fuse xt_mark ip6table_filter smsc95xx iio_trig_sysfs snd_seq_midi snd_seq_midi_event snd_rawmidi ip6_tables snd_seq snd_seq_device cros_ec_accel kfifo_buf industrialio iwlmvm cdc_ether usbnet mii iwlwifi btusb iwl7000_mac80211 btbcm btintel bluetooth cfg80211 uvcvideo videobuf2_vmalloc joydev 2017-08-14T20:29:38.563207-07:00 NOTICE kernel: [ 428.379876] CPU: 0 PID: 10712 Comm: DrmThread Tainted: G W 3.14.0 #1 2017-08-14T20:29:38.563209-07:00 NOTICE kernel: [ 428.379894] Hardware name: GOOGLE Samus, BIOS Google_Samus.6300.174.0 04/02/2015 2017-08-14T20:29:38.563211-07:00 NOTICE kernel: [ 428.379913] 0000000000000000 00000000c9acdfe5 ffff8803f6b918f0 ffffffffbf228b4c 2017-08-14T20:29:38.563214-07:00 NOTICE kernel: [ 428.379943] 0000000000000000 ffff8803f6b91928 ffffffffbec5d7e8 ffffffffbef626d4 2017-08-14T20:29:38.563216-07:00 NOTICE kernel: [ 428.379967] ffff8804686c1000 ffff880468719a08 ffff880468719800 ffff880467beaf48 2017-08-14T20:29:38.563218-07:00 NOTICE kernel: [ 428.379990] Call Trace: 2017-08-14T20:29:38.563221-07:00 NOTICE kernel: [ 428.380007] [<ffffffffbf228b4c>] dump_stack+0x4d/0x6f 2017-08-14T20:29:38.563247-07:00 NOTICE kernel: [ 428.380025] [<ffffffffbec5d7e8>] warn_slowpath_common+0x7f/0x98 2017-08-14T20:29:38.563250-07:00 NOTICE kernel: [ 428.380043] [<ffffffffbef626d4>] ? intel_crtc_wait_for_pending_flips+0xec/0x1b9 2017-08-14T20:29:38.563251-07:00 NOTICE kernel: [ 428.380061] [<ffffffffbec5d8fa>] warn_slowpath_null+0x1a/0x1c 2017-08-14T20:29:38.563253-07:00 NOTICE kernel: [ 428.380078] [<ffffffffbef626d4>] intel_crtc_wait_for_pending_flips+0xec/0x1b9 2017-08-14T20:29:38.563255-07:00 NOTICE kernel: [ 428.380098] [<ffffffffbec957bc>] ? finish_wait+0x62/0x62 2017-08-14T20:29:38.563257-07:00 NOTICE kernel: [ 428.380115] [<ffffffffbef68fcc>] haswell_crtc_disable+0x49/0x293 2017-08-14T20:29:38.563259-07:00 NOTICE kernel: [ 428.380133] [<ffffffffbef69ffa>] __intel_set_mode+0x98b/0x121e 2017-08-14T20:29:38.563261-07:00 NOTICE kernel: [ 428.380151] [<ffffffffbf230423>] ? _raw_spin_unlock+0xe/0x21 2017-08-14T20:29:38.563263-07:00 NOTICE kernel: [ 428.380168] [<ffffffffbef6c9e1>] intel_set_mode+0x14/0x2a 2017-08-14T20:29:38.563265-07:00 NOTICE kernel: [ 428.380185] [<ffffffffbef6d3a2>] intel_crtc_set_config+0x8a7/0x965 2017-08-14T20:29:38.563267-07:00 NOTICE kernel: [ 428.380206] [<ffffffffbef2bb7e>] drm_mode_set_config_internal+0x5b/0xe5 2017-08-14T20:29:38.563269-07:00 NOTICE kernel: [ 428.380225] [<ffffffffbef2c050>] drm_framebuffer_remove+0x185/0x230 2017-08-14T20:29:38.563271-07:00 NOTICE kernel: [ 428.380279] [<ffffffffbef2f782>] drm_fb_release+0xa9/0xc9 2017-08-14T20:29:38.563272-07:00 NOTICE kernel: [ 428.380297] [<ffffffffbef21956>] drm_release+0x28b/0x50b 2017-08-14T20:29:38.563297-07:00 NOTICE kernel: [ 428.380357] [<ffffffffbed493df>] __fput+0xe1/0x19a 2017-08-14T20:29:38.563299-07:00 NOTICE kernel: [ 428.380372] [<ffffffffbed494ce>] ____fput+0xe/0x10 2017-08-14T20:29:38.563301-07:00 NOTICE kernel: [ 428.380388] [<ffffffffbec78a17>] task_work_run+0x7d/0x93 2017-08-14T20:29:38.563303-07:00 NOTICE kernel: [ 428.380407] [<ffffffffbec5fad2>] do_exit+0x40d/0x94d 2017-08-14T20:29:38.563304-07:00 NOTICE kernel: [ 428.380426] [<ffffffffbec8e786>] ? update_cfs_shares+0xd0/0xd7 2017-08-14T20:29:38.563306-07:00 NOTICE kernel: [ 428.380450] [<ffffffffbec6aa61>] ? __dequeue_signal+0x1a/0x136 2017-08-14T20:29:38.563308-07:00 NOTICE kernel: [ 428.380471] [<ffffffffbec6008a>] do_group_exit+0x42/0xb0 2017-08-14T20:29:38.563313-07:00 NOTICE kernel: [ 428.380496] [<ffffffffbec6d79b>] get_signal_to_deliver+0x567/0x58d 2017-08-14T20:29:38.564118-07:00 NOTICE kernel: [ 428.380520] [<ffffffffbec01eb3>] do_signal+0x57/0x527 2017-08-14T20:29:38.564137-07:00 NOTICE kernel: [ 428.380543] [<ffffffffbec890d3>] ? wake_up_state+0x12/0x12 2017-08-14T20:29:38.564140-07:00 NOTICE kernel: [ 428.380564] [<ffffffffbec023ac>] do_notify_resume+0x29/0x5b 2017-08-14T20:29:38.564143-07:00 NOTICE kernel: [ 428.380584] [<ffffffffbf23172e>] int_signal+0x12/0x17 2017-08-14T20:29:38.564146-07:00 WARNING kernel: [ 428.380603] ---[ end trace fa32a8c47aa426ae ]--- And finally the kernel wait times out, but the test has already timed out.
,
Aug 15 2017
@tutankhamen Seeing that you just fixed a kernel warning in the i915 driver, can you take a look and help direct the bug to the right owner?
,
Aug 15 2017
,
Aug 15 2017
Issue 755635 has been merged into this issue.
,
Aug 15 2017
tutankhamen@, can you confirm whether this is fixed?
,
Aug 16 2017
Doesn't seem fixed. The failures are repeating.
,
Aug 16 2017
Stephane, can you set right owner for this? This seems to be also affecting CQ, see this build for example: https://luci-milo.appspot.com/buildbot/chromeos/auron_yuna-paladin/453
,
Aug 16 2017
Robert was the right owner...
,
Aug 16 2017
,
Aug 16 2017
,
Aug 17 2017
sent out the revert cl at https://chromium-review.googlesource.com/c/618221 assign to julanhsu@. We need someone to work on this bug.
,
Aug 17 2017
reassign it to myself
,
Aug 17 2017
The CL:599207 has been reverted at CL:618221. tutankhamen@ couldn't reproduce the issue with his CL on samus and auron-paine. We'll monitor the tree. If the issue still happens again on auron_yuna-paladin, the real bug is still on TOT. We need to merge CL:599207 back to master, and sheriffs@ please help to find the culprit CL.
,
Aug 18 2017
I don't think "intel_crtc_wait_for_pending_flips()" timeout has any relation to this bug. We had several such warnings before and I just fixed one of them. This warning means that "wait_for_pending_flips()" were invoked with inactive crtc. It, actually, doesn't block anything.
,
Aug 18 2017
Note the backtrace posted earlier. It clearly shows that the warning occurs in the process that is handling do_exit. Now the timeout that triggers the warning is 60 seconds, which delays the process exit long enough to time out the test too. 2017/08/18 10:17 "tutankhamen via monorail" < monorail+v2.2530874832@chromium.org>:
,
Aug 18 2017
Revert landed in 9853.0.0, let's keep monitoring the next build result.
,
Aug 18 2017
it looks like my patch triggers that bug. Now I can reproduce it and will try to find workaround.
,
Aug 18 2017
9853.0.0 build looks fine on all boards: https://luci-milo.appspot.com/buildbot/chromeos/auron_paine-release/1409 https://luci-milo.appspot.com/buildbot/chromeos/auron_yuna-release/1408 https://luci-milo.appspot.com/buildbot/chromeos/lulu-release/1412 https://luci-milo.appspot.com/buildbot/chromeos/samus-release/4581
,
Aug 18 2017
Now I'm trying to investigate why it's happening.
,
Aug 21 2017
Issue 755664 has been merged into this issue.
,
Aug 22 2017
,
Nov 2 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/third_party/kernel/+/98924ed38cb51567307821298f4121b5b0c1e494 commit 98924ed38cb51567307821298f4121b5b0c1e494 Author: Robert Tarasov <tutankhamen77@gmail.com> Date: Thu Nov 02 07:12:59 2017 CHROMIUM: drm/i915: Fixed "wait_for_vblank" timeout and "wait_for_pending_flips" timeout Fixed issue when wait_for_vblank could be invoked during crtc deinitialization when planes are already inactive. Also, fixed an issue with possible intel_crtc_wait_for_pending_flips() timeout during crtc deinitialization by adding one frame delay. BUG= chromium:692768 , chromium:755461 TEST=cat /var/log/messages | grep "vblank wait timed out" Change-Id: If65aff20945175dba64fea1b59565f840d8bbf27 Signed-off-by: Robert Tarasov <tutankhamen77@gmail.com> Reviewed-on: https://chromium-review.googlesource.com/626940 Commit-Ready: Robert Tarasov <tutankhamen@chromium.org> Tested-by: Robert Tarasov <tutankhamen@chromium.org> Reviewed-by: Stéphane Marchesin <marcheu@chromium.org> [modify] https://crrev.com/98924ed38cb51567307821298f4121b5b0c1e494/drivers/gpu/drm/i915/intel_display.c
,
Jan 22 2018
|
||||||||||||||
►
Sign in to add a comment |
||||||||||||||
Comment 1 by tfiga@chromium.org
, Aug 15 2017