New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Users are reporting extreme jank/hangs in dev

Project Member Reported by abodenha@chromium.org, Jul 11 2016

Issue description

Version: 53.0.2784.3
OS: Chrome

See https://feedback.corp.google.com/#/Report/10905610670
 
Owner: afakhry@chromium.org
Status: Assigned (was: Untriaged)
Status: Started (was: Assigned)

Comment 3 by wac@google.com, Jul 11 2016

By request of afakhry:

Index of /tmp/
Name	Size	Date Modified
[parent directory]		
.com.google.Chrome.4wcFET/		7/11/16, 10:25:35 AM
.com.google.Chrome.hhxdS6/		7/11/16, 9:25:16 AM
.com.google.Chrome.SSDcTS/		7/11/16, 10:13:30 AM
crash_sender.ZkUlaz/		7/11/16, 11:20:12 AM
.com.google.Chrome.6m1F81	18.8 kB	7/11/16, 10:09:48 AM
.com.google.Chrome.KDYBZc	18.8 kB	7/11/16, 11:17:34 AM
chromium-gpu-process-minidump-4d79280aa05e9e25.dmp	71.3 kB	7/11/16, 10:13:16 AM
disk-boot-complete	99 B	7/11/16, 9:25:17 AM
disk-chrome-exec	297 B	7/11/16, 10:25:24 AM
disk-chrome-first-render	99 B	7/11/16, 9:25:37 AM
disk-chrome-main	297 B	7/11/16, 10:25:35 AM
disk-lockbox-cache-end	99 B	7/11/16, 9:25:15 AM
disk-lockbox-cache-exec	99 B	7/11/16, 9:25:15 AM
disk-lockbox-cache-start	99 B	7/11/16, 9:25:15 AM
disk-login-prompt-visible	99 B	7/11/16, 9:25:17 AM
disk-login-start-signin-screen	99 B	7/11/16, 9:25:16 AM
disk-login-success	99 B	7/11/16, 9:25:24 AM
disk-login-wait-for-signin-state-initialize	99 B	7/11/16, 9:25:16 AM
disk-network-wifi-association	594 B	7/11/16, 3:15:12 PM
disk-network-wifi-configuration	594 B	7/11/16, 3:15:16 PM
disk-network-wifi-failure	297 B	7/11/16, 3:15:12 PM
disk-network-wifi-idle	396 B	7/11/16, 3:15:12 PM
disk-network-wifi-online	594 B	7/11/16, 3:15:18 PM
disk-network-wifi-ready	594 B	7/11/16, 3:15:18 PM
disk-post-startup	99 B	7/11/16, 9:25:15 AM
disk-pre-startup	99 B	7/11/16, 9:25:14 AM
disk-shill-start	99 B	7/11/16, 9:25:16 AM
firmware-boot-time	5 B	7/11/16, 9:25:18 AM
mount-encrypted.log	832 B	7/11/16, 9:25:17 AM
uptime-boot-complete	10 B	7/11/16, 9:25:17 AM
uptime-chrome-exec	42 B	7/11/16, 10:25:24 AM
uptime-chrome-first-render	12 B	7/11/16, 9:25:37 AM
uptime-chrome-main	42 B	7/11/16, 10:25:35 AM
uptime-lockbox-cache-end	10 B	7/11/16, 9:25:15 AM
uptime-lockbox-cache-exec	10 B	7/11/16, 9:25:15 AM
uptime-lockbox-cache-start	10 B	7/11/16, 9:25:15 AM
uptime-login-prompt-visible	10 B	7/11/16, 9:25:17 AM
uptime-login-start-signin-screen	10 B	7/11/16, 9:25:16 AM
uptime-login-success	12 B	7/11/16, 9:25:24 AM
uptime-login-wait-for-signin-state-initialize	10 B	7/11/16, 9:25:16 AM
uptime-network-wifi-association	90 B	7/11/16, 3:15:12 PM
uptime-network-wifi-configuration	90 B	7/11/16, 3:15:16 PM
uptime-network-wifi-failure	51 B	7/11/16, 3:15:12 PM
uptime-network-wifi-idle	63 B	7/11/16, 3:15:12 PM
uptime-network-wifi-online	91 B	7/11/16, 3:15:18 PM
uptime-network-wifi-ready	91 B	7/11/16, 3:15:18 PM
uptime-post-startup	10 B	7/11/16, 9:25:15 AM
uptime-pre-startup	10 B	7/11/16, 9:25:14 AM
uptime-shill-start	10 B	7/11/16, 9:25:16 AM
Cc: reinauer@google.com jch@google.com wac@google.com
Thanks.

I'm unable to repro on my Pixel 1. Is there anything I should do to trigger this?

Comment 5 by wac@google.com, Jul 11 2016

chrome_20160711-092516.txt
22.7 KB View Download
chrome_20160711-101329.txt
1.1 KB View Download
chrome_20160711-102534.txt
6.8 KB View Download
wac@ Can you please go to chrome://plugins/ and disable Adobe Flash Player? Does that improve things?
Still unable to repro. Tried on Pixel 1 on both ToT and 53.0.2784.3. No janks at all, everything is smooth.

wac@: If you are in MTV, maybe the best option is that I take a look at your device.
Cc: semenzato@chromium.org omrilio@chromium.org
+semenzato@: I need your help to figure out what's going on here:

A complete hang happened to omrilio@'s samus device today, and he brought it to me. The device was completely unresponsive, the only way to get out was to do a hard reset (Refresh + Power).

Taking a look at the logs. There seems to be something weird going on in the kernel. Starting at 11:28 AM to 11:33 AM it appears to be a loop of Suspend-to-RAM --> Resume --> Suspend-to-RAM --> Resume. Note that Omri said he didn't suspend his device.

I attached the file for you too look at it, but I copied here below the messages of interest:

2016-07-12T11:28:35.545927-07:00 INFO session_manager[1694]: [INFO:session_manager_impl.cc(524)] HandleLockScreenShown() method called.
2016-07-12T11:28:35.550742-07:00 INFO session_manager[1694]: [INFO:session_manager_impl.cc(520)] LockScreen() method called.
2016-07-12T11:28:36.195770-07:00 NOTICE powerd_suspend[24583]: Going to suspend-to-RAM state: args=--suspend_duration=-1 --nosuspend_to_idle --wakeup_count=492
2016-07-12T11:28:36.286253-07:00 NOTICE powerd_suspend[24637]: Explicit sync
2016-07-12T11:28:36.475956-07:00 NOTICE powerd_suspend[24639]: Finalizing suspend
2016-07-12T11:28:36.478237-07:00 INFO kernel: [ 1530.461275] PM: suspend entry 2016-07-12 18:28:36.477818518 UTC
2016-07-12T11:28:36.493238-07:00 INFO kernel: [ 1530.461288] PM: Syncing filesystems ... done.
2016-07-12T11:28:36.493258-07:00 DEBUG kernel: [ 1530.476332] PM: Preparing system for mem sleep
2016-07-12T11:28:57.369230-07:00 NOTICE kernel: [ 1530.489229] Freezing user space processes ... (elapsed 0.001 seconds) done.
2016-07-12T11:28:57.369243-07:00 NOTICE kernel: [ 1530.490969] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
2016-07-12T11:28:57.369246-07:00 DEBUG kernel: [ 1530.492401] PM: Entering mem sleep
2016-07-12T11:28:57.369248-07:00 INFO kernel: [ 1530.602093] calling  rfkill1+ @ 24642, parent: phy0, cb: rfkill_suspend
2016-07-12T11:28:57.369250-07:00 INFO kernel: [ 1530.602104] calling  1-2+ @ 67, parent: usb1, cb: usb_dev_suspend
2016-07-12T11:28:57.369252-07:00 INFO kernel: [ 1530.602112] call 1-2+ returned 0 after 1 usecs
2016-07-12T11:28:57.369254-07:00 INFO kernel: [ 1530.602149] call rfkill1+ returned 0 after 0 usecs
2016-07-12T11:28:57.369256-07:00 INFO kernel: [ 1530.602172] calling  phy0-led+ @ 24642, parent: 0000:01:00.0, cb: led_suspend
...
...
2016-07-12T11:28:57.370134-07:00 INFO kernel: [ 1531.946537] PM: noirq suspend of devices complete after 22.246 msecs
2016-07-12T11:28:57.370136-07:00 INFO kernel: [ 1531.947306] ACPI: Preparing to enter system sleep state S3
2016-07-12T11:28:57.370137-07:00 INFO kernel: [ 1531.947401] PM: Saving platform NVS memory
2016-07-12T11:28:57.370138-07:00 NOTICE kernel: [ 1531.947410] Disabling non-boot CPUs ...
2016-07-12T11:28:57.370141-07:00 NOTICE kernel: [ 1531.947982] Cannot set affinity for irq 60
2016-07-12T11:28:57.370142-07:00 INFO kernel: [ 1531.949852] smpboot: CPU 1 is now offline
2016-07-12T11:28:57.370144-07:00 INFO kernel: [ 1531.951962] smpboot: CPU 2 is now offline
2016-07-12T11:28:57.370145-07:00 INFO kernel: [ 1531.954116] smpboot: CPU 3 is now offline
2016-07-12T11:28:57.370209-07:00 INFO kernel: [ 1531.956387] Disabling VMX on cpu 0
2016-07-12T11:28:57.370211-07:00 INFO kernel: [ 1531.956394] TSC at resume: 559176614
2016-07-12T11:28:57.370215-07:00 INFO kernel: [ 1531.956398] ACPI: Low-level resume complete
2016-07-12T11:28:57.370218-07:00 INFO kernel: [ 1531.956455] PM: Restoring platform NVS memory
2016-07-12T11:28:57.370220-07:00 INFO kernel: [ 1531.956812] Enabling non-boot CPUs ...
2016-07-12T11:28:57.370221-07:00 INFO kernel: [ 1531.956854] x86: Booting SMP configuration:
2016-07-12T11:28:57.370223-07:00 INFO kernel: [ 1531.956859] smpboot: Booting Node 0 Processor 1 APIC 0x1
2016-07-12T11:28:57.370224-07:00 INFO kernel: [ 1531.967297] Disabling VMX on cpu 1
2016-07-12T11:28:57.370225-07:00 INFO kernel: [ 1531.971339] Intel pstate controlling: cpu 1
2016-07-12T11:28:57.370227-07:00 INFO kernel: [ 1531.971389] CPU1 is up
2016-07-12T11:28:57.370228-07:00 INFO kernel: [ 1531.971408] smpboot: Booting Node 0 Processor 2 APIC 0x3
2016-07-12T11:28:57.370231-07:00 INFO kernel: [ 1531.981814] Disabling VMX on cpu 2
2016-07-12T11:28:57.370232-07:00 INFO kernel: [ 1531.985783] Intel pstate controlling: cpu 2
2016-07-12T11:28:57.370234-07:00 INFO kernel: [ 1531.985825] CPU2 is up
2016-07-12T11:28:57.370235-07:00 INFO kernel: [ 1531.985843] smpboot: Booting Node 0 Processor 3 APIC 0x2
2016-07-12T11:28:57.370236-07:00 INFO kernel: [ 1531.996247] Disabling VMX on cpu 3
2016-07-12T11:28:57.370238-07:00 INFO kernel: [ 1532.000256] Intel pstate controlling: cpu 3
2016-07-12T11:28:57.370239-07:00 INFO kernel: [ 1532.000298] CPU3 is up
2016-07-12T11:28:57.370242-07:00 INFO kernel: [ 1532.003410] ACPI: Waking up from system sleep state S3
2016-07-12T11:28:57.370244-07:00 INFO kernel: [ 1532.003504] calling  0000:00:00.0+ @ 24642, parent: pci0000:00, cb: pci_pm_resume_noirq
2016-07-12T11:28:57.370246-07:00 INFO kernel: [ 1532.003525] call 0000:00:00.0+ returned 0 after 13 usecs
2016-07-12T11:28:57.370247-07:00 INFO kernel: [ 1532.003530] calling  0000:00:02.0+ @ 24642, parent: pci0000:00, cb: pci_pm_resume_noirq
2016-07-12T11:28:57.370249-07:00 INFO kernel: [ 1532.014253] call 0000:00:02.0+ returned 0 after 10453 usecs
...
...
2016-07-12T11:30:11.074988-07:00 WARNING kernel: [ 1606.103464] ------------[ cut here ]------------
2016-07-12T11:30:11.075004-07:00 WARNING kernel: [ 1606.103477] WARNING: CPU: 0 PID: 2311 at /mnt/host/source/src/third_party/kernel/v3.14/drivers/gpu/drm/i915/intel_display.c:767 intel_wait_for_vblank+0xe0/0x1ce()
2016-07-12T11:30:11.075007-07:00 NOTICE kernel: [ 1606.103487] vblank wait timed out
2016-07-12T11:30:11.075015-07:00 NOTICE kernel: [ 1606.103491] Modules linked in: ip6t_REJECT ctr ccm evdi uinput cmac i2c_dev x86_pkg_temp_thermal rfcomm iwlmvm aesni_intel memc_x86 aes_x86_64 glue_helper lrw gf128mul ablk_helper cryptd snd_soc_sst_bdw_rt5677_mach iwlwifi snd_hda_codec_hdmi iwl7000_mac80211 zram snd_hda_intel snd_hda_controller snd_hda_codec snd_hwdep acpi_als industrialio_triggered_buffer snd_soc_sst_haswell_pcm snd_soc_sst_dsp snd_soc_rt5677 fuse snd_soc_sst_acpi snd_soc_rl6231 snd_soc_rt5677_spi cfg80211 nf_conntrack_ipv6 nf_defrag_ipv6 ip6table_filter ip6_tables btusb btbcm btintel bluetooth iio_trig_sysfs uvcvideo videobuf2_vmalloc joydev cros_ec_accel kfifo_buf industrialio snd_seq_midi snd_seq_midi_event snd_rawmidi snd_seq snd_seq_device ppp_async ppp_generic slhc tun
2016-07-12T11:30:11.075017-07:00 NOTICE kernel: [ 1606.103610] CPU: 0 PID: 2311 Comm: DrmThread Not tainted 3.14.0 #1
2016-07-12T11:30:11.075019-07:00 NOTICE kernel: [ 1606.103617] Hardware name: GOOGLE Samus, BIOS Google_Samus.6300.174.0 04/02/2015
2016-07-12T11:30:11.075022-07:00 NOTICE kernel: [ 1606.103624]  0000000000000000 00000000180ff748 ffff8802674f79e0 ffffffffa0fa4d83
2016-07-12T11:30:11.075024-07:00 NOTICE kernel: [ 1606.103634]  ffff8802674f7a28 ffff8802674f7a18 ffffffffa0a3df6b ffffffffa0cff89c
2016-07-12T11:30:11.075026-07:00 NOTICE kernel: [ 1606.103644]  ffff880274928000 0000000000070040 0000000000000bae 000000010013e7a0
2016-07-12T11:30:11.075027-07:00 NOTICE kernel: [ 1606.103655] Call Trace:
2016-07-12T11:30:11.075030-07:00 NOTICE kernel: [ 1606.103663]  [<ffffffffa0fa4d83>] dump_stack+0x4d/0x6f
2016-07-12T11:30:11.075032-07:00 NOTICE kernel: [ 1606.103671]  [<ffffffffa0a3df6b>] warn_slowpath_common+0x7f/0x98
2016-07-12T11:30:11.075035-07:00 NOTICE kernel: [ 1606.103679]  [<ffffffffa0cff89c>] ? intel_wait_for_vblank+0xe0/0x1ce
2016-07-12T11:30:11.075036-07:00 NOTICE kernel: [ 1606.103687]  [<ffffffffa0a3dfdb>] warn_slowpath_fmt+0x57/0x73
2016-07-12T11:30:11.075038-07:00 NOTICE kernel: [ 1606.103695]  [<ffffffffa0d3716e>] ? gen6_read32+0xa4/0xb2
2016-07-12T11:30:11.075040-07:00 NOTICE kernel: [ 1606.103702]  [<ffffffffa0cff89c>] intel_wait_for_vblank+0xe0/0x1ce
2016-07-12T11:30:11.075042-07:00 NOTICE kernel: [ 1606.103710]  [<ffffffffa0d03fdc>] hsw_disable_ips+0x12b/0x14d
2016-07-12T11:30:11.075044-07:00 NOTICE kernel: [ 1606.103717]  [<ffffffffa0d0598a>] haswell_crtc_disable+0x6e/0x293
2016-07-12T11:30:11.075045-07:00 NOTICE kernel: [ 1606.103725]  [<ffffffffa0d0678e>] __intel_set_mode+0x78a/0x11ba
2016-07-12T11:30:11.075047-07:00 NOTICE kernel: [ 1606.103740]  [<ffffffffa0fa911b>] ? _raw_spin_unlock+0xe/0x21
2016-07-12T11:30:11.075049-07:00 NOTICE kernel: [ 1606.103748]  [<ffffffffa0fa7726>] ? __ww_mutex_lock_slowpath+0x286/0x2d9
2016-07-12T11:30:11.075051-07:00 NOTICE kernel: [ 1606.103756]  [<ffffffffa0d092fc>] intel_set_mode+0x14/0x2a
2016-07-12T11:30:11.075053-07:00 NOTICE kernel: [ 1606.103763]  [<ffffffffa0d09cb2>] intel_crtc_set_config+0x89c/0x95a
2016-07-12T11:30:11.075054-07:00 NOTICE kernel: [ 1606.103772]  [<ffffffffa0cca9c4>] ? drm_crtc_check_state+0x6c/0x221
2016-07-12T11:30:11.075057-07:00 NOTICE kernel: [ 1606.103780]  [<ffffffffa0cc804c>] drm_mode_set_config_internal+0x5b/0xe5
2016-07-12T11:30:11.075058-07:00 NOTICE kernel: [ 1606.103789]  [<ffffffffa0cd4f2a>] commit_crtc_state+0x165/0x21c
2016-07-12T11:30:11.075060-07:00 NOTICE kernel: [ 1606.103797]  [<ffffffffa0cd4ad5>] atomic_commit.isra.3+0x54/0xae
2016-07-12T11:30:11.075062-07:00 NOTICE kernel: [ 1606.103805]  [<ffffffffa0cd4b40>] drm_atomic_commit+0x11/0x13
2016-07-12T11:30:11.075064-07:00 NOTICE kernel: [ 1606.103813]  [<ffffffffa0ccb987>] drm_mode_setcrtc+0x2f2/0x392
2016-07-12T11:30:11.075066-07:00 NOTICE kernel: [ 1606.103821]  [<ffffffffa0cbd3a5>] drm_ioctl+0x2f2/0x421
2016-07-12T11:30:11.075068-07:00 NOTICE kernel: [ 1606.103828]  [<ffffffffa0ccb695>] ? drm_mode_setplane+0x9c/0x9c
2016-07-12T11:30:11.075070-07:00 NOTICE kernel: [ 1606.103837]  [<ffffffffa0b1c708>] do_vfs_ioctl+0x355/0x416
2016-07-12T11:30:11.075071-07:00 NOTICE kernel: [ 1606.103844]  [<ffffffffa0b24ec7>] ? __fget+0x6f/0x79
2016-07-12T11:30:11.075073-07:00 NOTICE kernel: [ 1606.103852]  [<ffffffffa0b1c820>] SyS_ioctl+0x57/0x79
2016-07-12T11:30:11.075075-07:00 NOTICE kernel: [ 1606.103859]  [<ffffffffa0faa2dd>] tracesys+0xda/0xdf
2016-07-12T11:30:11.075076-07:00 WARNING kernel: [ 1606.103943] ---[ end trace 83f0fc6c758fb14f ]---
2016-07-12T11:30:11.439547-07:00 INFO session_manager[1694]: [INFO:session_manager_impl.cc(524)] HandleLockScreenShown() method called.
2016-07-12T11:30:12.043176-07:00 NOTICE powerd_suspend[27120]: Going to suspend-to-RAM state: args=--suspend_duration=-1 --nosuspend_to_idle --wakeup_count=544
2016-07-12T11:30:12.145973-07:00 NOTICE powerd_suspend[27172]: Explicit sync
2016-07-12T11:30:12.358972-07:00 NOTICE powerd_suspend[27174]: Finalizing suspend
2016-07-12T11:30:12.362397-07:00 INFO kernel: [ 1607.393904] PM: suspend entry 2016-07-12 18:30:12.361549092 UTC
2016-07-12T11:30:12.381413-07:00 INFO kernel: [ 1607.393924] PM: Syncing filesystems ... done.
2016-07-12T11:30:12.381439-07:00 DEBUG kernel: [ 1607.412854] PM: Preparing system for mem sleep
2016-07-12T11:33:46.368029-07:00 NOTICE kernel: [ 1607.426973] Freezing user space processes ... (elapsed 0.001 seconds) done.
2016-07-12T11:33:46.368044-07:00 NOTICE kernel: [ 1607.428569] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
2016-07-12T11:33:46.368046-07:00 DEBUG kernel: [ 1607.429953] PM: Entering mem sleep
2016-07-12T11:33:46.368048-07:00 INFO kernel: [ 1607.548165] calling  1-7+ @ 24687, parent: usb1, cb: usb_dev_suspend
2016-07-12T11:33:46.368050-07:00 INFO kernel: [ 1607.548175] calling  rfkill1+ @ 27177, parent: phy0, cb: rfkill_suspend
2016-07-12T11:33:46.368052-07:00 INFO kernel: [ 1607.548185] call rfkill1+ returned 0 after 0 usecs
...
...
2016-07-12T11:33:46.374114-07:00 INFO kernel: [ 1609.053603] PM: Saving platform NVS memory
2016-07-12T11:33:46.374121-07:00 NOTICE kernel: [ 1609.053613] Disabling non-boot CPUs ...
2016-07-12T11:33:46.374123-07:00 INFO kernel: [ 1609.055978] smpboot: CPU 1 is now offline
2016-07-12T11:33:46.374125-07:00 INFO kernel: [ 1609.058092] smpboot: CPU 2 is now offline
2016-07-12T11:33:46.374196-07:00 INFO kernel: [ 1609.060243] smpboot: CPU 3 is now offline
2016-07-12T11:33:46.374198-07:00 INFO kernel: [ 1609.062448] Disabling VMX on cpu 0
2016-07-12T11:33:46.374199-07:00 INFO kernel: [ 1609.062456] TSC at resume: 559586198
2016-07-12T11:33:46.374208-07:00 INFO kernel: [ 1609.062460] ACPI: Low-level resume complete
2016-07-12T11:33:46.374210-07:00 INFO kernel: [ 1609.062516] PM: Restoring platform NVS memory
2016-07-12T11:33:46.374214-07:00 INFO kernel: [ 1609.062871] Enabling non-boot CPUs ...
2016-07-12T11:33:46.374216-07:00 INFO kernel: [ 1609.062914] x86: Booting SMP configuration:
2016-07-12T11:33:46.374217-07:00 INFO kernel: [ 1609.062919] smpboot: Booting Node 0 Processor 1 APIC 0x1
2016-07-12T11:33:46.374219-07:00 INFO kernel: [ 1609.073508] Disabling VMX on cpu 1
2016-07-12T11:33:46.374220-07:00 INFO kernel: [ 1609.077762] Intel pstate controlling: cpu 1
2016-07-12T11:33:46.374232-07:00 INFO kernel: [ 1609.077822] CPU1 is up
2016-07-12T11:33:46.374233-07:00 INFO kernel: [ 1609.077841] smpboot: Booting Node 0 Processor 2 APIC 0x3
2016-07-12T11:33:46.374237-07:00 INFO kernel: [ 1609.088247] Disabling VMX on cpu 2
2016-07-12T11:33:46.374239-07:00 INFO kernel: [ 1609.092320] Intel pstate controlling: cpu 2
2016-07-12T11:33:46.374240-07:00 INFO kernel: [ 1609.092364] CPU2 is up
2016-07-12T11:33:46.374242-07:00 INFO kernel: [ 1609.092381] smpboot: Booting Node 0 Processor 3 APIC 0x2
2016-07-12T11:33:46.374243-07:00 INFO kernel: [ 1609.102794] Disabling VMX on cpu 3
2016-07-12T11:33:46.374245-07:00 INFO kernel: [ 1609.106789] Intel pstate controlling: cpu 3
2016-07-12T11:33:46.374246-07:00 INFO kernel: [ 1609.106832] CPU3 is up
2016-07-12T11:33:46.374248-07:00 INFO kernel: [ 1609.109961] ACPI: Waking up from system sleep state S3
2016-07-12T11:33:46.374252-07:00 INFO kernel: [ 1609.110057] calling  0000:00:00.0+ @ 27177, parent: pci0000:00, cb: pci_pm_resume_noirq
2016-07-12T11:33:46.374254-07:00 INFO kernel: [ 1609.110077] call 0000:00:00.0+ returned 0 after 13 usecs
messages.txt
293 KB View Download
Hi, unfortunately I don't see anything unusual in that log.  The suspends are about 70 seconds apart which is not unusual---open the lid, use the laptop for one minute, close the lid again.

There is a fair amount of wifi activity, but it's probably unrelated.

I am guessing the problem is with chrome.

From what I understood from Omri, he didn't close the lid and reopen it twice like that, and that's why I was asking. Omri, can you please confirm whether those suspends were triggered by you? Thanks!
And yes, there seems to be a lot of wifi activity, trying to reach Google-A but unable to. Attached is the UI logs.
ui.txt
21.0 KB View Download
Cc: bartfab@chromium.org
Also, I'm not sure why there're a lot of error messages with this ID "oedeeodfidgoollimchfdnbmhcpnklnd". This seems to be the ID of the ZipUnpacker extension.

+bartfab@ to comment on the meaning of this

[1768:2206:0712/111911:ERROR:device_status_collector.cc(125)] Unable to get volume status for /special/drive-b63caefe04e8903f72975c402143e8c5e047f747
[1768:2206:0712/111911:ERROR:device_status_collector.cc(125)] Unable to get volume status for /provided/oedeeodfidgoollimchfdnbmhcpnklnd:~%2FDownloads%2F10500091531-system_logs%2Ezip:b63caefe04e8903f72975c402143e8c5e047f747
[1768:2206:0712/111911:ERROR:device_status_collector.cc(125)] Unable to get volume status for /provided/oedeeodfidgoollimchfdnbmhcpnklnd:~%2FDownloads%2FAndroid Wallpaper 2%2Ezip:b63caefe04e8903f72975c402143e8c5e047f747
[1768:2312:0712/112111:ERROR:device_status_collector.cc(125)] Unable to get volume status for /special/drive-b63caefe04e8903f72975c402143e8c5e047f747
[1768:2312:0712/112111:ERROR:device_status_collector.cc(125)] Unable to get volume status for /provided/oedeeodfidgoollimchfdnbmhcpnklnd:~%2FDownloads%2F10500091531-system_logs%2Ezip:b63caefe04e8903f72975c402143e8c5e047f747
[1768:2312:0712/112111:ERROR:device_status_collector.cc(125)] Unable to get volume status for /provided/oedeeodfidgoollimchfdnbmhcpnklnd:~%2FDownloads%2FAndroid Wallpaper 2%2Ezip:b63caefe04e8903f72975c402143e8c5e047f747
[1768:2206:0712/112311:ERROR:device_status_collector.cc(125)] Unable to get volume status for /special/drive-b63caefe04e8903f72975c402143e8c5e047f747
[1768:2206:0712/112311:ERROR:device_status_collector.cc(125)] Unable to get volume status for /provided/oedeeodfidgoollimchfdnbmhcpnklnd:~%2FDownloads%2F10500091531-system_logs%2Ezip:b63caefe04e8903f72975c402143e8c5e047f747
[1768:2206:0712/112311:ERROR:device_status_collector.cc(125)] Unable to get volume status for /provided/oedeeodfidgoollimchfdnbmhcpnklnd:~%2FDownloads%2FAndroid Wallpaper 2%2Ezip:b63caefe04e8903f72975c402143e8c5e047f747
[1768:2312:0712/112511:ERROR:device_status_collector.cc(125)] Unable to get volume status for /special/drive-b63caefe04e8903f72975c402143e8c5e047f747
[1768:2312:0712/112511:ERROR:device_status_collector.cc(125)] Unable to get volume status for /provided/oedeeodfidgoollimchfdnbmhcpnklnd:~%2FDownloads%2F10500091531-system_logs%2Ezip:b63caefe04e8903f72975c402143e8c5e047f747
[1768:2312:0712/112511:ERROR:device_status_collector.cc(125)] Unable to get volume status for /provided/oedeeodfidgoollimchfdnbmhcpnklnd:~%2FDownloads%2FAndroid Wallpaper 2%2Ezip:b63caefe04e8903f72975c402143e8c5e047f747
[1768:1768:0712/112708:ERROR:device_event_log_impl.cc(140)] [11:27:08.462] Network: network_state_handler.cc:618 DefaultNetworkPropertyUpdated: Google-A.Error = "out-of-range"
[1768:1768:0712/112708:ERROR:device_event_log_impl.cc(140)] [11:27:08.465] Network: network_state_handler.cc:921 Default network in unexpected state: Google-A (/service/5)State: failure
[1768:1768:0712/112708:ERROR:device_event_log_impl.cc(140)] [11:27:08.487] Network: network_state_handler.cc:618 NetworkPropertyUpdated: Google-A.Error = "Unknown"
[1768:1768:0712/112710:ERROR:device_event_log_impl.cc(140)] [11:27:10.382] Network: network_state_handler.cc:618 NetworkPropertyUpdated: Google-A.Error = "out-of-range"
[1768:1768:0712/112710:ERROR:device_event_log_impl.cc(140)] [11:27:10.385] Network: network_state_handler.cc:618 NetworkPropertyUpdated: Google-A.Error = "Unknown"
There's another thread with people discussing misbehavior of the zip unpacker. I just added you. Possibly related.
Cc: hirono@chromium.org mtomasz@chromium.org fukino@chromium.org
I just read it.
Adding some owners of the file manager app.
We didn't change ZIP unpacker recently. I got some report and it seems NaCL is misbehaving.
@afakhry -- I've been seeing this a lot, here are a couple observations as to when it seems to happen. Not sure whether causation or correlation, though.

1) I've been using my Samus (53.0.2785.4 dev) in docked mode with an external monitor for the majority of the past few days, and have not once had it hang while doing so. When I unplugged it and brought it over to the triage tent, the problem happened again within 30min. Maybe something related to non-native resolution?

2) Since my home wifi is down, I've been using my Samus (note: not in docked mode) on a tethered network recently. Whenever I start editing Google Docs, Samus seems to hang reliably every 5-10min or so. I've even tried restarting, but it still hangs.
Is it possible to record a trace when this happens? Or is it too unresponsive to do so?
When your system hangs, please try to unhang it with the alt-volumeup-X shortcut: try once, wait 3-4s, try again, wait 3-4s, try a third time.  This should cause either a Chrome restart or a full system restart.  Either way, please file feedback with alt-shift-i after the system is usable again.
I noticed that /opt/google/chrome/pepper/libpepflashplayer.so is always one of the top Dynamic Shared Objects with the highest number of samples, on CrOs Wide Profiling, lately on both link and samus (especially link) on M53. 

I don't remember this used to be the case before (maybe I'm wrong). I also don't know if this is related, but just in case. I've asked one of the affected users in comment #6 to disable Flash Player, but he didn't report back if it helped.

+ihf@ do you know if that's normal
Cc: ihf@chromium.org
Adding +ihf@ for the previous comment.

Comment 21 by ihf@chromium.org, Jul 14 2016

Flash should only the third highest process on https://uma.googleplex.com/chromeos_wide_profiling
I don't see it being the highest for the link/samus selections I have done. Can you share the link?
I didn't say it's the top one, but rather one of the top DSOs. I can see it as the third one as well. It seems from your comment that this should be normal. If so, I should look for other suspicions. 
Issue 628345 has been merged into this issue.
Cc: steve...@chromium.org osh...@chromium.org dbehr@chromium.org adurbin@chromium.org marc...@chromium.org xiy...@chromium.org
After looking at a bunch of logs from various users, I noticed that the most common messages I see that are logged right before the hangs are drm related. As an example:

[1:17:0711/205503:ERROR:ffmpeg_demuxer.cc(1510)] OnReadFrameDone result=-541478725 IsMaxMemoryUsageReached=0
[1:1:0711/205513:WARNING:webmediaplayer_impl.cc(335)] Using MultibufferDataSource
[1:17:0711/205528:ERROR:ffmpeg_demuxer.cc(1510)] OnReadFrameDone result=-541478725 IsMaxMemoryUsageReached=0
[27967:27974:0711/205539:WARNING:screen_manager.cc(100)] Display controller (crtc=20) already present.
[27967:27974:0711/205539:VERBOSE1:drm_display.cc(102)] DRM configuring: device=/sys/devices/pci0000:00/0000:00:02.0/drm/card0 crtc=20 connector=29 origin=0,0 size=0x0
[27967:27974:0711/210025:WARNING:screen_manager.cc(100)] Display controller (crtc=20) already present.
[27967:27974:0711/210025:VERBOSE1:drm_display.cc(102)] DRM configuring: device=/sys/devices/pci0000:00/0000:00:02.0/drm/card0 crtc=20 connector=29 origin=0,0 size=2560x1700
[27967:27974:0711/210026:WARNING:screen_manager.cc(100)] Display controller (crtc=20) already present.
[27967:27974:0711/210026:VERBOSE1:drm_display.cc(102)] DRM configuring: device=/sys/devices/pci0000:00/0000:00:02.0/drm/card0 crtc=20 connector=29 origin=0,0 size=2560x1700

Also, a lot of errors related to not being able to get a status of a volume, sometimes mentions the ID of ZipPacker. Something like the following:

[19908:19945:0714/091925:ERROR:device_status_collector.cc(119)] Unable to get volume status for /provided/oedeeodfidgoollimchfdnbmhcpnklnd:~%2FDownloads%2Fbugreport-NMD90D-2016-07-12-14-10-32 (1)%2Ezip:f591db025f8d78409c77e27d6a5e856f74d08a65
[19908:19928:0714/092125:ERROR:device_status_collector.cc(119)] Unable to get volume status for /special/drive-1fe927c193a23a3a8c74168173ec4ec971ad6a11
[19908:19928:0714/092125:ERROR:device_status_collector.cc(119)] Unable to get volume status for /special/drive-f591db025f8d78409c77e27d6a5e856f74d08a65
[19908:19928:0714/092125:ERROR:device_status_collector.cc(119)] Unable to get volume status for /provided/oedeeodfidgoollimchfdnbmhcpnklnd:~%2FDownloads%2Fbugreport-NMD90D-2016-07-12-14-10-32 (1)%2Ezip:f591db025f8d78409c77e27d6a5e856f74d08a65

Those however are far too common, so I'm not so sure if they mean anything serious.

On the kernel messages, the common things are:
1- The following stack trace is often printed:
2016-07-12T11:30:11.074988-07:00 WARNING kernel: [ 1606.103464] ------------[ cut here ]------------
2016-07-12T11:30:11.075004-07:00 WARNING kernel: [ 1606.103477] WARNING: CPU: 0 PID: 2311 at /mnt/host/source/src/third_party/kernel/v3.14/drivers/gpu/drm/i915/intel_display.c:767 intel_wait_for_vblank+0xe0/0x1ce()
2016-07-12T11:30:11.075007-07:00 NOTICE kernel: [ 1606.103487] vblank wait timed out
2016-07-12T11:30:11.075015-07:00 NOTICE kernel: [ 1606.103491] Modules linked in: ip6t_REJECT ctr ccm evdi uinput cmac i2c_dev x86_pkg_temp_thermal rfcomm iwlmvm aesni_intel memc_x86 aes_x86_64 glue_helper lrw gf128mul ablk_helper cryptd snd_soc_sst_bdw_rt5677_mach iwlwifi snd_hda_codec_hdmi iwl7000_mac80211 zram snd_hda_intel snd_hda_controller snd_hda_codec snd_hwdep acpi_als industrialio_triggered_buffer snd_soc_sst_haswell_pcm snd_soc_sst_dsp snd_soc_rt5677 fuse snd_soc_sst_acpi snd_soc_rl6231 snd_soc_rt5677_spi cfg80211 nf_conntrack_ipv6 nf_defrag_ipv6 ip6table_filter ip6_tables btusb btbcm btintel bluetooth iio_trig_sysfs uvcvideo videobuf2_vmalloc joydev cros_ec_accel kfifo_buf industrialio snd_seq_midi snd_seq_midi_event snd_rawmidi snd_seq snd_seq_device ppp_async ppp_generic slhc tun
2016-07-12T11:30:11.075017-07:00 NOTICE kernel: [ 1606.103610] CPU: 0 PID: 2311 Comm: DrmThread Not tainted 3.14.0 #1
2016-07-12T11:30:11.075019-07:00 NOTICE kernel: [ 1606.103617] Hardware name: GOOGLE Samus, BIOS Google_Samus.6300.174.0 04/02/2015
2016-07-12T11:30:11.075022-07:00 NOTICE kernel: [ 1606.103624]  0000000000000000 00000000180ff748 ffff8802674f79e0 ffffffffa0fa4d83
2016-07-12T11:30:11.075024-07:00 NOTICE kernel: [ 1606.103634]  ffff8802674f7a28 ffff8802674f7a18 ffffffffa0a3df6b ffffffffa0cff89c
2016-07-12T11:30:11.075026-07:00 NOTICE kernel: [ 1606.103644]  ffff880274928000 0000000000070040 0000000000000bae 000000010013e7a0
2016-07-12T11:30:11.075027-07:00 NOTICE kernel: [ 1606.103655] Call Trace:
2016-07-12T11:30:11.075030-07:00 NOTICE kernel: [ 1606.103663]  [<ffffffffa0fa4d83>] dump_stack+0x4d/0x6f
2016-07-12T11:30:11.075032-07:00 NOTICE kernel: [ 1606.103671]  [<ffffffffa0a3df6b>] warn_slowpath_common+0x7f/0x98
2016-07-12T11:30:11.075035-07:00 NOTICE kernel: [ 1606.103679]  [<ffffffffa0cff89c>] ? intel_wait_for_vblank+0xe0/0x1ce
2016-07-12T11:30:11.075036-07:00 NOTICE kernel: [ 1606.103687]  [<ffffffffa0a3dfdb>] warn_slowpath_fmt+0x57/0x73
2016-07-12T11:30:11.075038-07:00 NOTICE kernel: [ 1606.103695]  [<ffffffffa0d3716e>] ? gen6_read32+0xa4/0xb2
2016-07-12T11:30:11.075040-07:00 NOTICE kernel: [ 1606.103702]  [<ffffffffa0cff89c>] intel_wait_for_vblank+0xe0/0x1ce
2016-07-12T11:30:11.075042-07:00 NOTICE kernel: [ 1606.103710]  [<ffffffffa0d03fdc>] hsw_disable_ips+0x12b/0x14d
2016-07-12T11:30:11.075044-07:00 NOTICE kernel: [ 1606.103717]  [<ffffffffa0d0598a>] haswell_crtc_disable+0x6e/0x293
2016-07-12T11:30:11.075045-07:00 NOTICE kernel: [ 1606.103725]  [<ffffffffa0d0678e>] __intel_set_mode+0x78a/0x11ba
2016-07-12T11:30:11.075047-07:00 NOTICE kernel: [ 1606.103740]  [<ffffffffa0fa911b>] ? _raw_spin_unlock+0xe/0x21
2016-07-12T11:30:11.075049-07:00 NOTICE kernel: [ 1606.103748]  [<ffffffffa0fa7726>] ? __ww_mutex_lock_slowpath+0x286/0x2d9
2016-07-12T11:30:11.075051-07:00 NOTICE kernel: [ 1606.103756]  [<ffffffffa0d092fc>] intel_set_mode+0x14/0x2a
2016-07-12T11:30:11.075053-07:00 NOTICE kernel: [ 1606.103763]  [<ffffffffa0d09cb2>] intel_crtc_set_config+0x89c/0x95a
2016-07-12T11:30:11.075054-07:00 NOTICE kernel: [ 1606.103772]  [<ffffffffa0cca9c4>] ? drm_crtc_check_state+0x6c/0x221
2016-07-12T11:30:11.075057-07:00 NOTICE kernel: [ 1606.103780]  [<ffffffffa0cc804c>] drm_mode_set_config_internal+0x5b/0xe5
2016-07-12T11:30:11.075058-07:00 NOTICE kernel: [ 1606.103789]  [<ffffffffa0cd4f2a>] commit_crtc_state+0x165/0x21c
2016-07-12T11:30:11.075060-07:00 NOTICE kernel: [ 1606.103797]  [<ffffffffa0cd4ad5>] atomic_commit.isra.3+0x54/0xae
2016-07-12T11:30:11.075062-07:00 NOTICE kernel: [ 1606.103805]  [<ffffffffa0cd4b40>] drm_atomic_commit+0x11/0x13
2016-07-12T11:30:11.075064-07:00 NOTICE kernel: [ 1606.103813]  [<ffffffffa0ccb987>] drm_mode_setcrtc+0x2f2/0x392
2016-07-12T11:30:11.075066-07:00 NOTICE kernel: [ 1606.103821]  [<ffffffffa0cbd3a5>] drm_ioctl+0x2f2/0x421
2016-07-12T11:30:11.075068-07:00 NOTICE kernel: [ 1606.103828]  [<ffffffffa0ccb695>] ? drm_mode_setplane+0x9c/0x9c
2016-07-12T11:30:11.075070-07:00 NOTICE kernel: [ 1606.103837]  [<ffffffffa0b1c708>] do_vfs_ioctl+0x355/0x416
2016-07-12T11:30:11.075071-07:00 NOTICE kernel: [ 1606.103844]  [<ffffffffa0b24ec7>] ? __fget+0x6f/0x79
2016-07-12T11:30:11.075073-07:00 NOTICE kernel: [ 1606.103852]  [<ffffffffa0b1c820>] SyS_ioctl+0x57/0x79
2016-07-12T11:30:11.075075-07:00 NOTICE kernel: [ 1606.103859]  [<ffffffffa0faa2dd>] tracesys+0xda/0xdf
2016-07-12T11:30:11.075076-07:00 WARNING kernel: [ 1606.103943] ---[ end trace 83f0fc6c758fb14f ]---

2- A lot of suspends followed by immediate unsuspends! For example:
  -- User (A): Suspend and resume happened within the same second @ 11:33:46!
2016-07-12T11:33:46.368029-07:00 NOTICE kernel: [ 1607.426973] Freezing user space processes ... (elapsed 0.001 seconds) done.
2016-07-12T11:33:46.368044-07:00 NOTICE kernel: [ 1607.428569] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
2016-07-12T11:33:46.368046-07:00 DEBUG kernel: [ 1607.429953] PM: Entering mem sleep
....
2016-07-12T11:33:46.374111-07:00 INFO kernel: [ 1609.052742] PM: noirq suspend of devices complete after 22.264 msecs
2016-07-12T11:33:46.374112-07:00 INFO kernel: [ 1609.053510] ACPI: Preparing to enter system sleep state S3
2016-07-12T11:33:46.374114-07:00 INFO kernel: [ 1609.053603] PM: Saving platform NVS memory
2016-07-12T11:33:46.374121-07:00 NOTICE kernel: [ 1609.053613] Disabling non-boot CPUs ...
2016-07-12T11:33:46.374123-07:00 INFO kernel: [ 1609.055978] smpboot: CPU 1 is now offline
2016-07-12T11:33:46.374125-07:00 INFO kernel: [ 1609.058092] smpboot: CPU 2 is now offline
2016-07-12T11:33:46.374196-07:00 INFO kernel: [ 1609.060243] smpboot: CPU 3 is now offline
2016-07-12T11:33:46.374198-07:00 INFO kernel: [ 1609.062448] Disabling VMX on cpu 0
2016-07-12T11:33:46.374199-07:00 INFO kernel: [ 1609.062456] TSC at resume: 559586198  <<<<------ **** Resume ****
2016-07-12T11:33:46.374208-07:00 INFO kernel: [ 1609.062460] ACPI: Low-level resume complete
2016-07-12T11:33:46.374210-07:00 INFO kernel: [ 1609.062516] PM: Restoring platform NVS memory
2016-07-12T11:33:46.374214-07:00 INFO kernel: [ 1609.062871] Enabling non-boot CPUs ...
...
2016-07-12T11:33:46.377948-07:00 INFO kernel: [ 1609.407534] PM: resume of devices complete after 241.916 msecs
2016-07-12T11:33:46.377951-07:00 INFO kernel: [ 1609.430702] haswell-pcm-audio haswell-pcm-audio: FW loaded, mailbox readback FW info: type 01, - version: 00.00, build 77, source commit id: 876ac6906f31a43b6772b23c7c983ce9dcb18a19
2016-07-12T11:33:46.377952-07:00 DEBUG kernel: [ 1609.431003] PM: Finishing wakeup.
2016-07-12T11:33:46.377954-07:00 NOTICE kernel: [ 1609.431006] Restarting tasks ... done.
2016-07-12T11:33:46.377955-07:00 INFO kernel: [ 1609.432278] PM: suspend exit 2016-07-12 18:33:46.369060590 UTC
2016-07-12T11:33:46.377958-07:00 INFO kernel: [ 1609.435339] usb 1-7: USB disconnect, device number 9
2016-07-12T11:33:46.390029-07:00 NOTICE powerd_suspend[27188]: wake source: SMI_STS: MCSMI GPE0 PM1 #015 PM1_STS: WAK #015 GPE0_STS: GPIO27 #015
2016-07-12T11:33:46.392167-07:00 NOTICE powerd_suspend[27214]: Resume finished

  -- User (B): Also within the same second @ second 1276 from startup.
[ 1276.069164] PM: suspend entry 2016-07-13 20:51:34.087032405 UTC
[ 1276.069183] PM: Syncing filesystems ... done.
[ 1276.111700] PM: Preparing system for mem sleep
[ 1276.112407] Freezing user space processes ... (elapsed 0.001 seconds) done.
[ 1276.113915] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[ 1276.115062] PM: Entering mem sleep
...
[ 1276.501652] PM: noirq suspend of devices complete after 22.264 msecs
[ 1276.502666] ACPI: Preparing to enter system sleep state S3
[ 1276.502762] PM: Saving platform NVS memory
[ 1276.502771] Disabling non-boot CPUs ...
[ 1276.505413] smpboot: CPU 1 is now offline
[ 1276.508441] smpboot: CPU 2 is now offline
[ 1276.510414] smpboot: CPU 3 is now offline
[ 1276.512861] Disabling VMX on cpu 0
[ 1276.512869] TSC at resume: 671271344    <<<<<------ **** Resume ****
[ 1276.512872] ACPI: Low-level resume complete
[ 1276.512927] PM: Restoring platform NVS memory
[ 1276.513278] Enabling non-boot CPUs ...
[ 1276.513321] x86: Booting SMP configuration:
...
[ 1276.830450] PM: resume of devices complete after 214.276 msecs
[ 1276.850262] haswell-pcm-audio haswell-pcm-audio: no context buffer need to restore!
[ 1276.850270] haswell-pcm-audio haswell-pcm-audio: no context buffer need to restore!
[ 1276.852717] haswell-pcm-audio haswell-pcm-audio: FW loaded, mailbox readback FW info: type 01, - version: 00.00, build 77, source commit id: 876ac6906f31a43b6772b23c7c983ce9dcb18a19
[ 1276.853010] PM: Finishing wakeup.
[ 1276.853012] Restarting tasks ... done.

Adding a few more folks to help out make sense of this.
Cc: dnicoara@chromium.org
Re #24: The DRM calls seem consistent with the suspend/resume actions mentioned. At least from the sample, it seems like the system suspended (or at least was idle) at 20:55:39 (at which point the display is disabled) followed by activity at 21:00:25 which re-enables the display.

The kernel warning looks to be a result of the display being disabled. Given that the warning mentions that the "vblank wait timed out", I can believe there was a hang caused by the display disable.
I had a freeze&crash yesterday around 17:30. Here are logs

https://docs.google.com/document/d/1HOaf0upqJyDzTRrGMk5dL_XPbbw8u44-ZQqyOzUzv64/edit
Re #27: Can you please share the complete kernel messages too? I want to see what happened before 17:29, i.e. before:
2016-07-14T17:29:24.913786-07:00 ERR session_manager[575]: [ERROR:object_proxy.cc(582)] Failed to call method: org.chromium.LibCrosServiceInterface.CheckLiveness: object_path= /org/chromium/LibCrosService: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.
2016-07-14T17:29:59.928325-07:00 WARNING session_manager[575]: [WARNING:liveness_checker_impl.cc(68)] Browser hang detected!
2016-07-14T17:29:59.928351-07:00 WARNING session_manager[575]: [WARNING:liveness_checker_impl.cc(72)] Aborting browser process.
2016-07-14T17:29:59.930390-07:00 INFO session_manager[575]: [INFO:browser_job.cc(119)] Terminating process: Browser did not respond to DBus liveness check.


Nothing stands out from the other logs other than the following network error at 17:25:
[606:606:0714/172545:ERROR:device_event_log_impl.cc(140)] [17:25:45.232] Network: device_event_log.cc:117 @@@ Slow method: ../../../../../../../home/chrome-bot/chrome_root/src/chromeos/network/network_state_handler.cc:NotifyNetworkPropertiesUpdated: 59ms
[606:606:0714/172545:ERROR:device_event_log_impl.cc(140)] [17:25:45.233] Network: device_event_log.cc:117 @@@ Slow method: ../../../../../../../home/chrome-bot/chrome_root/src/chromeos/network/network_state_handler.cc:UpdateNetworkServiceProperty: 60ms

Cc: chrisha@chromium.org georgesak@chromium.org haraken@chromium.org
I did more investigations today. I think all the errors we saw above are just side effects of the actual problem. I managed to repro the issue by creating a bunch of apps that keep allocating memory. After a certain level, the machine just freeze! It comes back after a while though. The duration of the varies.

I think the issue has to do with memory pressure listeners, V8 GC, or zram. I have to look more into this.
+georgesak@ and +chrisha@ Has anything changed in memory pressure handling recently on M53?
Cc: cylee@chromium.org
Cheng-yu has been working with memory management for arc++ recently.  There may be some related bug already open.

It is possible that zram/app killing needs more tuning.  If you can replicate this, it may be useful to try my suggestion in #18.  However it is possible for the system to thrash without the kernel producing any related logs.  

It would also be interesting to watch "top" as you start more apps (before it hangs completely, of course) and check swap usage as well as kswapd cpu percentage.

Cc: bccheng@chromium.org
Cc: cywang@chromium.org hctsai@chromium.org
I took a look at system_logs.zip in the feedback report mentioned in issue 628345. Per the ps section, the process with #1 CPU usage was the Chrome's browser process (73.2%) but #2 was something called 'flashrom' (35.5%), which I never heard of.

For some reason, there was no 'ps' section in system_logs.zip in https://feedback.corp.google.com/#/Report/10905610670



Re #33, flashrom was documented at https://docs.google.com/document/d/1H8zZ3aEMZmfO4ZEsWbHooUdGOgxy5LTPJ19YbaDsxdQ/edit?hl=en . I guess the issue 628345 was about a device getting slow during auto update, that's different from the new jank issues discussed in this bug...
Flashrom updates the r/w firmware.  It can happen right after an OS update, but it should be rare, i.e. most os updates don't update the firmware.  Also, it should add very little CPU load, and only for a short time (a minute or less).
On a separate email thread (not yet associated with a bug, but search for "smaps" in the near future) we noticed that the task monitor makes an excessive number of reads of /proc/*/smaps, which are expensive.  Closing the task monitor seemed to make a big difference.  Was the task monitor open during these experiments?
Re#36: The task manager reads totmaps rather than smaps. Does it have the same effect?
Using a samus for several days on dev without issue off campus. On campus today and seeing this repeatedly. When its happening its too bad to get anything useful from the device, logs etc. Environment differences are wifi network (non broadcast admin defined using https://chrome.google.com/webstore/detail/fhndealchbngfhdoncgcokameljahhog)  and a dell D3100. Anecdotally, so far, it seems dock induced.
tbuckley@ also reported location as a factor.
#37 Yes, totmaps and smaps both walk the PTEs.

#38 By "dock induced" do you mean connected to an external display?  What resolution?  Thanks!
Yeah connected to dock (D3100) that is connected to external displays

1920x1080 Internal + 1600x900 External + 1920x1080 External

This is with no ethernet or other USB plugged in - just displays.

Generally, within 5 min of plugging the dock in the machine is janky/hung. Tomorrow I'll try some permutations of matching or not resolution and 1 or >1 external displays and report back. So far running with just the dock with nothing plugged into it is fine.
#41 would it be possible for you to run "top" in a crosh and take a screenshot when the machine starts getting janky but before it is hung?  I know I may be asking for too much.  (Also I am taking some time off starting tomorrow so it may be a while before I personally look at this, but someone else might.)  Thanks!
Any ideas on why 'ps' section was missing in https://feedback.corp.google.com/#/Report/10905610670 ? The feedback also missed many other sections such as bios_info, cpuinfo, lsmod, and more.
No worries, that's not too much. So I was able to get close to right before it goes bad but the screenshoting hangs until the it comes back (if it does at all) if I wait too long. What I see is displayLinkManager takes over (SS 1&2) but top stops updating, visibly at least, and you get to the last two SS's if it does come back.

Also, even though the actual displays only draw the cursor (no background or windows as stated by someone else before) the screenshots show what should be on the display.
Screenshot 2016-07-19 at 6.03.35 PM - Display 1.png
245 KB View Download
Screenshot 2016-07-19 at 6.03.37 PM - Display 1.png
252 KB View Download
Screenshot 2016-07-19 at 6.03.40 PM - Display 1.png
244 KB View Download
Screenshot 2016-07-19 at 6.03.43 PM - Display 1.png
247 KB View Download
Cc: adamk@chromium.org ishell@chromium.org jochen@chromium.org u...@chromium.org
The only way I could get the machine into a state where the browser process is constantly using more than 100% CPU was by logging into ChromeOS 53.0.2785.15/8530 using my corp account and opening a bunch of links from Google News.

I recorded a perf for 20 seconds, and the report shows that the majority of samples recorded for Chrome are spent in V8 apparently handling heap operations.

+Adding some V8 folks.

Attached the report file (mangled C++ symbols). I'm pasting here the top symbols after I demangled them.

# Overhead  Command          Shared Object     Symbol
# ........  ...............  ................. .................................
#
    14.99%  chrome           chrome            [.] void v8::internal::BodyDescriptorBase::IteratePointers<v8::internal::MarkCompactMarkingVisitor>(v8::internal::Heap*, v8::internal::HeapObject*, int, int)
    10.39%  swapper          [kernel.kallsyms] [k] intel_idle
     5.07%  chrome           chrome            [.] v8::internal::StaticMarkingVisitor<v8::internal::MarkCompactMarkingVisitor>::MarkMapContents(v8::internal::Heap*, v8::internal::Map*)
     4.85%  chrome           chrome            [.] v8::internal::HashTable<v8::internal::WeakHashTable, v8::internal::WeakHashTableShape<2>, v8::internal::Handle<v8::internal::Object> >::Rehash(v8::internal::Handle<v8::internal::Object>)
     3.64%  chrome           chrome            [.] v8::internal::HeapObject::SizeFromMap(v8::internal::Map*)
     2.72%  chrome           chrome            [.] v8::internal::MarkCompactCollector::EmptyMarkingDeque()
     2.69%  chrome           chrome            [.] int v8::internal::MarkCompactCollector::Sweeper::RawSweep<(v8::internal::MarkCompactCollector::Sweeper::SweepingMode)0, (v8::internal::MarkCompactCollector::Sweeper::SweepingParallelism)1, (v8::internal::MarkCompactCollector::Sweeper::SkipListRebuildingMode)1, (v8::internal::MarkCompactCollector::Sweeper::FreeListRebuildingMode)0, (v8::internal::MarkCompactCollector::Sweeper::FreeSpaceTreatmentMode)0>(v8::internal::PagedSpace*, v8::internal::Page*, v8::internal::ObjectVisitor*)
     2.63%  chrome           chrome            [.] v8::internal::StaticMarkingVisitor<v8::internal::MarkCompactMarkingVisitor>::VisitJSFunction(v8::internal::Map*, v8::internal::HeapObject*)
     2.07%  chrome           chrome            [.] v8::internal::LiveObjectIterator<(v8::internal::LiveObjectIterationMode)0>::Next()
     1.98%  chrome           chrome            [.] v8::internal::MarkCompactCollector::ClearWeakCells(v8::internal::Object**, v8::internal::DependentCode**)
     0.89%  chrome           chrome            [.] v8::internal::StaticMarkingVisitor<v8::internal::MarkCompactMarkingVisitor>::VisitSharedFunctionInfoStrongCode(v8::internal::Heap*, v8::internal::HeapObject*)
     0.83%  chrome           chrome            [.] tc_malloc
     0.82%  chrome           chrome            [.] void v8::internal::RelocInfo::Visit<v8::internal::MarkCompactMarkingVisitor>(v8::internal::Heap*)
     0.81%  chrome           chrome            [.] v8::internal::JSFunction::ClearTypeFeedbackInfoAtGCTime()
     0.78%  chrome           chrome            [.] void v8::internal::FlexibleBodyVisitor<v8::internal::MarkCompactMarkingVisitor, v8::internal::FlexibleBodyDescriptor<8>, void>::VisitSpecialized<56>(v8::internal::Map*, v8::internal::HeapObject*)
     0.78%  chrome           chrome            [.] v8::internal::StaticMarkingVisitor<v8::internal::MarkCompactMarkingVisitor>::VisitWeakCell(v8::internal::Map*, v8::internal::HeapObject*)
     0.76%  chrome           chrome            [.] v8::internal::FreeList::Free(unsigned char*, int, v8::internal::FreeMode)
     0.74%  chrome           chrome            [.] v8::internal::RootMarkingVisitor::VisitPointer(v8::internal::Object**)
     0.65%  chrome           chrome            [.] void v8::internal::FlexibleBodyVisitor<v8::internal::MarkCompactMarkingVisitor, v8::internal::FlexibleBodyDescriptor<8>, void>::VisitSpecialized<32>(v8::internal::Map*, v8::internal::HeapObject*)
     0.61%  WorkerPool/639   chrome            [.] int v8::internal::MarkCompactCollector::Sweeper::RawSweep<(v8::internal::MarkCompactCollector::Sweeper::SweepingMode)0, (v8::internal::MarkCompactCollector::Sweeper::SweepingParallelism)1, (v8::internal::MarkCompactCollector::Sweeper::SkipListRebuildingMode)1, (v8::internal::MarkCompactCollector::Sweeper::FreeListRebuildingMode)0, (v8::internal::MarkCompactCollector::Sweeper::FreeSpaceTreatmentMode)0>(v8::internal::PagedSpace*, v8::internal::Page*, v8::internal::ObjectVisitor*)
     0.56%  chrome           chrome            [.] tc_free
     0.55%  WorkerPool/640   chrome            [.] int v8::internal::MarkCompactCollector::Sweeper::RawSweep<(v8::internal::MarkCompactCollector::Sweeper::SweepingMode)0, (v8::internal::MarkCompactCollector::Sweeper::SweepingParallelism)1, (v8::internal::MarkCompactCollector::Sweeper::SkipListRebuildingMode)1, (v8::internal::MarkCompactCollector::Sweeper::FreeListRebuildingMode)0, (v8::internal::MarkCompactCollector::Sweeper::FreeSpaceTreatmentMode)0>(v8::internal::PagedSpace*, v8::internal::Page*, v8::internal::ObjectVisitor*)
     0.52%  WorkerPool/640   chrome            [.] v8::internal::HeapObject::SizeFromMap(v8::internal::Map*)
     0.51%  WorkerPool/641   chrome            [.] int v8::internal::MarkCompactCollector::Sweeper::RawSweep<(v8::internal::MarkCompactCollector::Sweeper::SweepingMode)0, (v8::internal::MarkCompactCollector::Sweeper::SweepingParallelism)1, (v8::internal::MarkCompactCollector::Sweeper::SkipListRebuildingMode)1, (v8::internal::MarkCompactCollector::Sweeper::FreeListRebuildingMode)0, (v8::internal::MarkCompactCollector::Sweeper::FreeSpaceTreatmentMode)0>(v8::internal::PagedSpace*, v8::internal::Page*, v8::internal::ObjectVisitor*)
     0.49%  chrome           chrome            [.] v8::internal::FlexibleBodyVisitor<v8::internal::MarkCompactMarkingVisitor, v8::internal::FlexibleBodyDescriptor<16>, void>::Visit(v8::internal::Map*, v8::internal::HeapObject*)
     0.49%  WorkerPool/639   chrome            [.] v8::internal::HeapObject::SizeFromMap(v8::internal::Map*)
     0.48%  WorkerPool/639   chrome            [.] v8::internal::LiveObjectIterator<(v8::internal::LiveObjectIterationMode)0>::Next()
     0.44%  WorkerPool/640   chrome            [.] v8::internal::LiveObjectIterator<(v8::internal::LiveObjectIterationMode)0>::Next()
     0.38%  chrome           chrome            [.] v8::internal::Isolate::IsAnyInitialArrayPrototype(v8::internal::Handle<v8::internal::JSArray>)
     0.38%  WorkerPool/641   chrome            [.] v8::internal::HeapObject::SizeFromMap(v8::internal::Map*)
     0.38%  chrome           chrome            [.] v8::internal::PointersUpdatingVisitor::VisitPointer(v8::internal::Object**)
     0.37%  swapper          [kernel.kallsyms] [k] dw_readl
     0.37%  WorkerPool/641   chrome            [.] v8::internal::LiveObjectIterator<(v8::internal::LiveObjectIterationMode)0>::Next()
report.txt
5.2 MB View Download
Re#43: This is probably a bug. Nothing should be dropped. At first glance, this function looks suspicious: https://cs.chromium.org/chromium/src/components/feedback/feedback_common.cc?q=LogsToString&sq=package:chromium&l=50

I'll verify and take care of that.
I've got new samus with 53.0.2785.15 / 8530.13.0 dev (old one just died),  and started having very weird freeze.

It happened on amazon and a few other sites. When it happens, the render and browser's CPU usage goes up to 200 and UI becomes unresponsive. I could open task manager and kill them in most cases, but for other cases, I had to kill chrome using volume up + alt+ x.

One of the stack was really weird. It looks like it's spinning inside pthread.

https://crash.corp.google.com/browse?stbtiq=e2fcb3f600000000

Thread 0 CRASHED [SIGABRT @ 0x00000000 ] MAGIC SIGNATURE THREAD
0x00007f513221ad84	(libpthread-2.19.so + 0x0000ed84 )	__lll_lock_wait
0x00007f5132215fe5	(libpthread-2.19.so + 0x00009fe5 )	_L_lock_1109
0x00007f5132215fe5	(libpthread-2.19.so + 0x00009fe5 )	_L_lock_1109
0x00007f5132215fe5	(libpthread-2.19.so + 0x00009fe5 )	_L_lock_1109
0x00007f5132215fe5	(libpthread-2.19.so + 0x00009fe5 )	_L_lock_1109
0x00007f5132215fe5	(libpthread-2.19.so + 0x00009fe5 )	_L_lock_1109
0x00007f5132215fe5	(libpthread-2.19.so + 0x00009fe5 )	_L_lock_1109
0x00007f5132215fe5	(libpthread-2.19.so + 0x00009fe5 )	_L_lock_1109
.....

just fyi.
can you create a trace using chrome://tracing?
Cc: llozano@chromium.org
+llozano@

Has anyone tried bisecting this? If it coincides with the GYP -> GN switch then there is a chance that a compilation change may be triggering this.

Cc: laszio@chromium.org
I dont think so. This is reported on 53 and enabled GN on 54. 
Ah, so it is, somehow I was under the impression this was only affecting 54. Nevermind then. *whew*

Cc: abodenha@chromium.org dhadd...@chromium.org sdantul...@chromium.org rookrishna@chromium.org
 Issue 629901  has been merged into this issue.
Re #48: jochen, I added you to an e-mail thread in which I shared a trace and perf reports.
Is this only happening with touch screen models? And tablets?

I was able to get this tracker page to hang while viewing an attached file in Beta 52. 

Dev 53 is a total disaster on my Flip. But 53 is running more processes, two machines actually, and it's July, and it's a little warm. (and I don't have AC.)

So the display gets too hot and goes to sleep. (Can't complain, we do the same thing when our brains get too hot.) There probably is another scenario where system can't figure if the screen is actually being touched or not since the nominal surface temp is too high.

Chrome tends to run a bit warm, right? So you can have your Chrome and Android too. But not in July and August (unless the AC is cranked.)

Comment 55 Deleted

Comment 56 by mbw@google.com, Jul 22 2016

https://bugs.chromium.org/p/chromium/issues/detail?id=630651 is Chrome OS hanging hard, then showing a black screen, then coming back to a desktop with just a Chrome tab open (and everything else closed).

Agree with #29, seems correlated with low memory.

Re: #54, no, it happened to me an a non-touchscreen Chromebox.

Comment 57 by cylee@google.com, Jul 22 2016

FWIW, according to #29 if it's related to lowmemory management, it could also be affected by a recent regression (started around .. 7/11). Android kernel lowmemorykiller was re-activated by accident (b/30193036). It would pick victims to kill when memory is low *before* swap is fully used. That's why it should be disabled and switch to new lowmemory management mechanism which take swap into consideration.

Android lowmemorykiller is already removed by Dylan in latest official build. 
Just in cast, if you see lines like 
lowmemorykiller: Killing 'Media' (24173), adj 370,) ...
in dmesg, please disable lowmemorykiller temporarily by

echo '1001,1001,1001,1001,1001,10001' > /sys/modules/lowmemorykiller/parameters/adj
echo '0,0,0,0,0,0' > /sys/modules/lowmemorykiller/parameters/minfree

And see if it makes any difference.
Re#57: Users have reported this hang with CPU usage of browser process and sometimes another tab reaches around 200%, even when they have few tabs open with low memory consumption.

We actually suspect a finch experiment. Possibly something related to QUIC. Most discussion about this bug are in emails to affected users. I will share my findings here once I confirm them.
Labels: Restrict-View-Google
FWIW I experienced this multiple times and filed feedback reports both times. Let me know if there's anything I can do additionally if I encounter the hang again.
Labels: -Restrict-View-Google
Cc: sadrul@chromium.org keta...@chromium.org wjmaclean@chromium.org bokan@chromium.org rbyers@chromium.org moh...@chromium.org
We found the cause of this bug. The new pinch-to-zoom feature recently enabled on M53 is causing an IPC message cycle, where we get an infinite number of the "ViewHostMsg_PageScaleFactorChanged" IPC message to WebContentsImpl::OnMessageReceived() on the IO thread, causing the CPU usage of both the Browser process and the renderer to reach around 200%.

This is the culprit CL: https://codereview.chromium.org/2034213002.

The cycle I'm talking about is:

+-> content::WebContentsImpl::OnMessageReceived()
^  |
|  +-> content::WebContentsImpl::OnPageScaleFactorChanged()
|    |
|    +-> content::WebContentsObserver::OnPageScaleFactorChanged()
|      |
|      +-> guest_view::GuestViewBase::OwnerContentsObserver::OnPageScaleFactorChanged()
|        |
|        +-> content::WebContentsImpl::SetPageScale() --> Sends a message ViewMsg_SetPageScale.
|          |
|          +-> content::RenderViewImpl::OnMessageReceived()
|            |
|            +-> content::RenderViewImpl::OnSetPageScale()
|              |
|              +-> blink::WebViewImpl::setPageScaleFactor()
|                |
|                +-> blink::VisualViewport::setScale()
|                  |
|                  +-> blink::VisualViewport::setScaleAndLocation()
|                    |
|                    +-> blink::ChromeClientImpl::pageScaleFactorChanged()
|                      |
|                      +-> blink::WebViewImpl::pageScaleFactorChanged()
|                        |
|                        +-> content::RenderViewImpl::pageScaleFactorChanged() --> Sends a message ViewHostMsg_PageScaleFactorChanged
|                          |
+<-------------------------+

Comment 63 by bokan@chromium.org, Jul 26 2016

Cc: ymalik@chromium.org
 Issue 631313  has been merged into this issue.

Comment 64 by w...@chromium.org, Jul 26 2016

I've just had my Chromebox get into a high-jank state (it started responding sporadically to mouse input, then appeared to hang and after a minute or two it rebooted). Do we expect that this can repro even without a trackpad?
#64, we believe that there are different issues that are causing jank.  crbug.com/624456  (one you filed) is one of them at least.
Cc: asimjour@chromium.org
What's the plan now? 

- Revert this CL: https://codereview.chromium.org/2034213002? 
- Or go ahead with disabling pinch-to-zoom altogether as in https://chromium-review.googlesource.com/#/c/363491/1 and https://chromium-review.googlesource.com/#/c/363550/1 by asimjour@?
- Or fix the IPC cycle?
Re#67: No, it's not. There will be conflicts.
It's unclear what triggers the slowness (maybe it's mentioned in the comments, but difficult to find). For example, does the slowness happen if the user isn't doing anything at all? When the user is using the touchpad to move the mouse cursor? When the user is trying to use the touchpad to 2-finger scroll? When contemplating the purpose of life?

Re the IPC cycle mentioned earlier: when a page has a <webview>, and the main page is scaled, then, I think, this is expected. The sequence is as follows:

 1. The embedder/main-page changes the scale factor in response to pinch-zoom, and notifies the browser.
 2. Browser receives this information (WebContentsImpl::OnMessageReceived()), and notifies the observers.
 3. GuestView had installed an observer on the embedder (i.e. main-page) so that it can update the scale-factor of the embedders. This observer now triggers, which sends an IPC to the guest renderer to change the scale.
 4. The guest renderer receives the message, tells blink to update the scale factor.
 5. The guest page changes the scale factor, and notifies the browser.

One of the webview owners should confirm if this is indeed the case.

Some possibly useful changes to try out:

 1. Track the set scale factor in WebContentsImpl, so that OnPageScaleFactorChanged() does not notify the observers when the scale factor does not actually change (or there's a minimum threshold that needs to be exceeded before observers are notified, maybe) https://cs.chromium.org/chromium/src/content/browser/web_contents/web_contents_impl.cc?sq=package:chromium&dr=CSs&rcl=1469531834&l=3550

 2. Track the scale factor set in step 4 in content::RenderViewImpl, and avoid the IPC back to the browser in step 5 above.

Comment 70 by bokan@chromium.org, Jul 26 2016

There's a wrinkle here in that trackpad pinch gestures need to first send a wheel event that the page can use to preventDefault the default pinch-zoom action (e.g. Google Maps does this). Unfortunately, the pinch gesture synthesizes a wheel event inside the renderer/Blink which means that the pinch gesture has to be routed to the process the frame is in. If the wheel event isn't consumed, it looks like we try to apply pinch-zoom there but that's wrong, pinch-zoom should be applied in the top-most renderer. This probably breaks an assumption somewhere else about inner frames not having any pinch-zoom applied. 
Re#69: Sadrul, sorry for the vague repro conditions, most discussions about this bug has been on a long email thread with some affected users (to which you have been added recently).

I managed to repro by continuously and aggressively scrolling and pinching on the touchpad while browsing in a tab. It seems to happen when users accidentally make a pinch-to-zoom gesture while scrolling with two fingers. The exact repro steps are unknown.

Comment 72 by mbw@google.com, Jul 26 2016

https://bugs.chromium.org/p/chromium/issues/detail?id=628345 should probably be un-duped, as it occurred on a device with no touchscreen/touchpad.
Re#72: There's another issue we found while working on this one: https://bugs.chromium.org/p/chromium/issues/detail?id=624456 which happens when you have a tab with a high memory usage. The V8 GC will consume a lot of CPU that the UI will completely freeze!

How was your memory consumption in issue 628345?

Comment 74 by mbw@google.com, Jul 26 2016

In issue 628345, I vaguely recall being surprised there were single Chrome processes taking 500 MB - 1 GB each, likely totaling close to the 4 GB physical RAM the device has.

Compared to issue 630651, which was on the same device, issue 628345 does not show any oom-killer activity.

But yeah, they both sound like  issue 624456 .
Here is the step to repro if you have a test image on Samus:

1. Get touchpad event node by evtest(Here mine is /dev/input/event4)

localhost ~ # evtest
No device specified, trying to scan all of /dev/input/event*
Available devices:
/dev/input/event0:      Lid Switch
/dev/input/event1:      Power Button
/dev/input/event10:     bdw-rt5677 Headphone Jack
/dev/input/event2:      Power Button
/dev/input/event3:      AT Translated Set 2 keyboard
/dev/input/event4:      Atmel maXTouch Touchpad
/dev/input/event5:      Atmel maXTouch Touchscreen
/dev/input/event6:      HDA Intel HDMI HDMI/DP,pcm=8
/dev/input/event7:      HDA Intel HDMI HDMI/DP,pcm=7
/dev/input/event8:      HDA Intel HDMI HDMI/DP,pcm=3
/dev/input/event9:      bdw-rt5677 Mic Jack

2. Open a website e.g. www.cnn.com in a tab, close all other tabs, i.e. make sure cnn tab is the first tab.

3. ctrl-alt-t to open a terminal, then type 'shell' -> 'sudo su' -> 'cat touch.log | evemu-play --insert-slot0 /dev/input/event4'

4. wait until the end of the trackpad events playback, you should be able to hear the noise of fan.


janky.log
1.4 MB View Download

Comment 76 by hctsai@google.com, Jul 27 2016

I have truncated most no effect events from cywang's janky.log. The attached one could reproduce the issue in shorter time period. Be sure to place the cursor in center of the screen before running evemu-play.
janky.log
100 KB View Download
Attached please find another short recorded gesture to reproduce this issue on any tab.
janky.log
93.6 KB View Download
Cc: adlr@chromium.org
I could reproduce the issue with the same gesture on minnie-cheets R54-8558.0.0 - Here is what I did:

Use thumb and index finger to do the pinch-zooming, then third finger arrives for a second, then thumb leaves. Use the remaining two finger to scroll. If the page could not be moved, then yes, you just reproduce the issue. You might need to try several times to get it right.
Labels: -Pri-1 -ReleaseBlock-Stable ReleaseBlock-Beta Pri-0
Currently holding beta for this. I just realized we hadn't reflected that in the bug.
Is the disable landed and merged to 53?
Should we lower it back to ReleaseBlock-Stable now that the pinch-to-zoom feature has been disabled?

Comment 83 by ketakid@google.com, Jul 27 2016

Yes please :)
Labels: -ReleaseBlock-Beta ReleaseBlock-Stable
Labels: -Pri-0 Pri-1
At this point I'd question RBS as well. Punting pinch-to-zoom on the trackpad to 54 would not be catastrophic.
I've narrowed down hangs in multiple apps being related to syncing.

Crosh/Secure Shell hangs for me and Remote Desktop App (not Chrome RDP, but a Microsoft RDP one). 

Crosh doesn't hang for me as Guest, but definitely as user. More details here:

https://bugs.chromium.org/p/chromium/issues/detail?id=628223
Found something. According to top seems Chrome_FileThread gets hung/stuck at 99% CPU. It's taking way longer than it should.

Crosh commands that read the harddisk (git status, git checkout) can take forever. It's not just Crosh, but anything that's using the local storage. The Files App, or Caret come to a crawling halt when it gets into its crazy loop.

It seems related to Android apps because all that jank goes away when I disable Android apps. 

I've tried ls /proc/*/fd and lsof, but I can't really narrow it down. 

Right now I'm waiting for a simple git commit from Crosh and it's taking well over 5 minutes to complete. 

Comment 89 by w...@chromium.org, Aug 3 2016

FYI I've just had a jank/hang that lasted for ~10s or so, and seems correllated with high and frequent kswap0 activity listed in "top". Filed a feedback report and mentioned " crbug.com/627183 " in it. :)
afakhry@ M53 Stable launch is coming soon. This bug is labelled as Stable ReleaseBlock, pls make sure to land the fix asap so it gets chance to bake in beta before stable promotion. Thank you.
Cc: afakhry@chromium.org
Labels: -M-53 M-54
Owner: asimjour@chromium.org
Status: Assigned (was: Started)
The pinch-to-zoom feature has been disabled already. I will reassign to asimjour@ for triage. We'll have to make sure that this feature doesn't cause the same hang when it's re-enabled.
I'll also punt this to M54.
Status: Fixed (was: Assigned)
I think the main issue that led to this bug is fixed and landed in 53 already: the IPC misbehavior triggered by pinch to zoom.

I'm marking this fixed. Let's file more bugs to track anything remaining.

wez@ can you file a new bug for your hang/stall in #89?
If anyone intends to re-enable pinch-to-zoom in 53 please file a bug for that as well.
Owner: afakhry@chromium.org
I'll take it back then.
Status: Verified (was: Fixed)
not repro on Chrome Version: 55.0.2883.20/Chrome OS: 8872.16.0

Sign in to add a comment