New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.
Starred by 4 users
Status: Fixed
Owner:
Closed: Aug 22
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 0
Type: Bug



Sign in to add a comment
auron_paine, lulu, samus, auron_yuna: Timeout in intel_crtc_wait_for_pending_flips() when restarting/stopping chrome
Project Member Reported by tfiga@chromium.org, Aug 15 Back to list
Chrome 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.

 
Cc: puthik@chromium.org marc...@chromium.org hoegsberg@chromium.org seanpaul@chromium.org
Summary: auron_paine, lulu, samus: Timeout in intel_crtc_wait_for_pending_flips() when restarting/stopping chrome (was: auron_paine, lulu: Timeout in intel_crtc_wait_for_pending_flips() when restarting chrome)
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.
Cc: tutankhamen@chromium.org
@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?
Summary: auron_paine, lulu, samus, auron_yuna: Timeout in intel_crtc_wait_for_pending_flips() when restarting/stopping chrome (was: auron_paine, lulu, samus: Timeout in intel_crtc_wait_for_pending_flips() when restarting/stopping chrome)
Cc: tfiga@chromium.org nxia@chromium.org julanhsu@chromium.org chirantan@chromium.org
 Issue 755635  has been merged into this issue.
Owner: tutankhamen@chromium.org
tutankhamen@, can you confirm whether this is fixed?
Doesn't seem fixed. The failures are repeating.
Owner: marc...@chromium.org
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

Owner: tutankhamen@chromium.org
Robert was the right owner...
Labels: -Pri-1 Pri-0
Owner: julanhsu@chromium.org
sent out the revert cl at https://chromium-review.googlesource.com/c/618221


assign to julanhsu@. We need someone to work on this bug.
Owner: tutankhamen@chromium.org
reassign it to myself
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.
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.
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>:
Revert landed in 9853.0.0, let's keep monitoring the next build result.
it looks like my patch triggers that bug. Now I can reproduce it and will try to  find workaround. 
Now I'm trying to investigate why it's happening.
Issue 755664 has been merged into this issue.
Status: Fixed
Project Member Comment 24 by bugdroid1@chromium.org, Nov 2
Labels: merge-merged-chromeos-3.14
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

Sign in to add a comment