You are not logged in.
Pages: 1
Dear All,
Ran into quite an issue on my laptop (Asus UX305CA, 8GB RAM, Intel m3 6y30, 256GB SSD with btrfs) with cpu_iowait. Every time I copy something to or from a usb thumb drive (ext4, FAT32) with nautilus, dd or rsync the iowait goes high and system simply hangs.
In glances the iowait is around 20-23% after the usb storage is plugged in which is pretty high already in my understanding..
I got quite some critical errors:
2016-10-21 10:48:29 (0:00:13) - WARNING on CPU_IOWAIT (23.4)
2016-10-21 10:47:17 (0:00:10) - WARNING on CPU_IOWAIT (23.4)
2016-10-21 10:47:04 (0:00:07) - WARNING on CPU_IOWAIT (23.3)
2016-10-21 10:46:36 (0:00:13) - WARNING on CPU_IOWAIT (23.1)
2016-10-21 10:42:15 (0:04:15) - CRITICAL on CPU_IOWAIT (Min:22.8 Mean:41.3 Max:50.6): usb-storage, nautilus, xf86-video-intel-backlight-helper, uget-gtk
2016-10-21 10:41:53 (0:00:18) - CRITICAL on CPU_IOWAIT (Min:23.1 Mean:29.4 Max:44.8): firefox, usb-storage, xf86-video-intel-backlight-helper
2016-10-21 10:41:18 (0:00:12) - WARNING on CPU_IOWAIT (23.7)
2016-10-21 10:40:37 (0:00:22) - CRITICAL on CPU_IOWAIT (Min:23.8 Mean:34.0 Max:41.2): usb-storage, xf86-video-intel-backlight-helper, uget-gtk
2016-10-21 10:40:21 (0:00:13) - CRITICAL on CPU_IOWAIT (Min:24.9 Mean:34.6 Max:48.0): firefox, usb-storage, xf86-video-intel-backlight-helperDmesg output:
╭─apinter@ZenArch ~
╰─$ dmesg | grep sdb 1 ↵
[ 1794.449784] sd 2:0:0:0: [sdb] 15523840 512-byte logical blocks: (7.95 GB/7.40 GiB)
[ 1794.450016] sd 2:0:0:0: [sdb] Write Protect is off
[ 1794.450019] sd 2:0:0:0: [sdb] Mode Sense: 03 00 00 00
[ 1794.450241] sd 2:0:0:0: [sdb] No Caching mode page found
[ 1794.450244] sd 2:0:0:0: [sdb] Assuming drive cache: write through
[ 1794.462422] sdb: sdb1 sdb2 < sdb5 sdb6 sdb7 >
[ 1794.465573] sd 2:0:0:0: [sdb] Attached SCSI removable disk
[ 1798.079299] EXT4-fs (sdb5): mounted filesystem with ordered data mode. Opts: (null)
[ 1798.082169] EXT4-fs (sdb7): recovery complete
[ 1798.082175] EXT4-fs (sdb7): mounted filesystem with ordered data mode. Opts: (null)
[ 3066.315091] sdb: detected capacity change from 7948206080 to 0
[19795.011531] sd 2:0:0:0: [sdb] Spinning up disk...
[19798.019920] sd 2:0:0:0: [sdb] 1953525167 512-byte logical blocks: (1.00 TB/932 GiB)
[19798.019930] sd 2:0:0:0: [sdb] 2048-byte physical blocks
[19798.171533] sd 2:0:0:0: [sdb] Write Protect is off
[19798.171547] sd 2:0:0:0: [sdb] Mode Sense: 4f 00 00 00
[19798.171778] sd 2:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[19798.183031] sdb: sdb1
[19798.184718] sd 2:0:0:0: [sdb] Attached SCSI disk
[19807.077457] device-mapper: table: 254:0: adding target device sdb1 caused an alignment inconsistency: physical_block_size=4096, logical_block_size=512, alignment_offset=0, start=33553920
[19807.077461] device-mapper: table: 254:0: adding target device sdb1 caused an alignment inconsistency: physical_block_size=4096, logical_block_size=512, alignment_offset=0, start=33553920
[19954.501118] sd 2:0:0:0: [sdb] Synchronizing SCSI cache
[19954.599664] sd 2:0:0:0: [sdb] Synchronize Cache(10) failed: Result: hostbyte=0x07 driverbyte=0x00
[24038.734693] sd 2:0:0:0: [sdb] Spinning up disk...
[24041.744029] sd 2:0:0:0: [sdb] 1953525167 512-byte logical blocks: (1.00 TB/932 GiB)
[24041.744033] sd 2:0:0:0: [sdb] 2048-byte physical blocks
[24041.889134] sd 2:0:0:0: [sdb] Write Protect is off
[24041.889144] sd 2:0:0:0: [sdb] Mode Sense: 4f 00 00 00
[24041.889363] sd 2:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[24041.900611] sdb: sdb1
[24041.902356] sd 2:0:0:0: [sdb] Attached SCSI disk
[24068.903313] sd 2:0:0:0: [sdb] Synchronizing SCSI cache
[24069.001349] sd 2:0:0:0: [sdb] Synchronize Cache(10) failed: Result: hostbyte=0x07 driverbyte=0x00
[24070.742553] sd 2:0:0:0: [sdb] Spinning up disk...
[24072.748526] sd 2:0:0:0: [sdb] 1953525167 512-byte logical blocks: (1.00 TB/932 GiB)
[24072.748531] sd 2:0:0:0: [sdb] 2048-byte physical blocks
[24072.902475] sd 2:0:0:0: [sdb] Write Protect is off
[24072.902484] sd 2:0:0:0: [sdb] Mode Sense: 4f 00 00 00
[24072.902657] sd 2:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[24072.913858] sdb: sdb1
[24072.957889] sd 2:0:0:0: [sdb] Attached SCSI disk
[24083.658142] device-mapper: table: 254:0: adding target device sdb1 caused an alignment inconsistency: physical_block_size=4096, logical_block_size=512, alignment_offset=0, start=33553920
[24083.658150] device-mapper: table: 254:0: adding target device sdb1 caused an alignment inconsistency: physical_block_size=4096, logical_block_size=512, alignment_offset=0, start=33553920
[25170.604813] sd 2:0:0:0: [sdb] Synchronizing SCSI cache
[25170.708403] sd 2:0:0:0: [sdb] Synchronize Cache(10) failed: Result: hostbyte=0x07 driverbyte=0x00
[39738.905317] sd 2:0:0:0: [sdb] 61056064 512-byte logical blocks: (31.3 GB/29.1 GiB)
[39738.906541] sd 2:0:0:0: [sdb] Write Protect is off
[39738.906554] sd 2:0:0:0: [sdb] Mode Sense: 43 00 00 00
[39738.906868] sd 2:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[39738.918866] sdb: sdb1
[39738.920487] sd 2:0:0:0: [sdb] Attached SCSI removable disk
[40584.404986] sdb: detected capacity change from 31260704768 to 0
[44363.874708] sd 2:0:0:0: [sdb] Spinning up disk...
[44366.883903] sd 2:0:0:0: [sdb] 1953525167 512-byte logical blocks: (1.00 TB/932 GiB)
[44366.883907] sd 2:0:0:0: [sdb] 2048-byte physical blocks
[44367.032534] sd 2:0:0:0: [sdb] Write Protect is off
[44367.032549] sd 2:0:0:0: [sdb] Mode Sense: 4f 00 00 00
[44367.032772] sd 2:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[44367.044052] sdb: sdb1
[44367.045529] sd 2:0:0:0: [sdb] Attached SCSI disk
[44374.749745] device-mapper: table: 254:0: adding target device sdb1 caused an alignment inconsistency: physical_block_size=4096, logical_block_size=512, alignment_offset=0, start=33553920
[44374.749752] device-mapper: table: 254:0: adding target device sdb1 caused an alignment inconsistency: physical_block_size=4096, logical_block_size=512, alignment_offset=0, start=33553920
[45290.591482] sd 2:0:0:0: [sdb] Synchronizing SCSI cache
[45294.215639] sd 2:0:0:0: [sdb] Synchronizing SCSI cache
[45294.315540] sd 2:0:0:0: [sdb] Synchronize Cache(10) failed: Result: hostbyte=0x07 driverbyte=0x00
[45659.927244] sd 2:0:0:0: [sdb] 61056064 512-byte logical blocks: (31.3 GB/29.1 GiB)
[45659.928455] sd 2:0:0:0: [sdb] Write Protect is off
[45659.928469] sd 2:0:0:0: [sdb] Mode Sense: 43 00 00 00
[45659.928809] sd 2:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[45659.946364] sdb: sdb1
[45659.948612] sd 2:0:0:0: [sdb] Attached SCSI removable disk
[47195.069345] sd 2:0:0:0: [sdb] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x01 driverbyte=0x00
[47195.069350] sd 2:0:0:0: [sdb] tag#0 CDB: opcode=0x2a 2a 00 01 92 ff 80 00 00 90 00
[47195.069352] blk_update_request: I/O error, dev sdb, sector 26410880
[47195.069356] Buffer I/O error on dev sdb1, logical block 3301104, lost async page write
[47195.069362] Buffer I/O error on dev sdb1, logical block 3301105, lost async page write
[47195.069364] Buffer I/O error on dev sdb1, logical block 3301106, lost async page write
[47195.069366] Buffer I/O error on dev sdb1, logical block 3301107, lost async page write
[47195.069368] Buffer I/O error on dev sdb1, logical block 3301108, lost async page write
[47195.069370] Buffer I/O error on dev sdb1, logical block 3301109, lost async page write
[47195.069372] Buffer I/O error on dev sdb1, logical block 3301110, lost async page write
[47195.069374] Buffer I/O error on dev sdb1, logical block 3301111, lost async page write
[47195.069376] Buffer I/O error on dev sdb1, logical block 3301112, lost async page write
[47195.069378] Buffer I/O error on dev sdb1, logical block 3301113, lost async page write
[47195.072414] sd 2:0:0:0: [sdb] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x01 driverbyte=0x00
[47195.072417] sd 2:0:0:0: [sdb] tag#0 CDB: opcode=0x2a 2a 00 01 93 7f 80 00 00 90 00
[47195.072419] blk_update_request: I/O error, dev sdb, sector 26443648Journalctl output:
╭─apinter@ZenArch ~
╰─$ journalctl -xe
Oct 21 10:49:06 ZenArch kernel: sd 2:0:0:0: [sdb] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x01 driverbyte=0x00
Oct 21 10:49:06 ZenArch kernel: sd 2:0:0:0: [sdb] tag#0 CDB: opcode=0x2a 2a 00 01 93 7f 80 00 00 90 00
Oct 21 10:49:06 ZenArch kernel: blk_update_request: I/O error, dev sdb, sector 26443648
Oct 21 10:49:06 ZenArch ntfs-3g[25556]: Unmounting /dev/sdb1 ()
Oct 21 10:49:06 ZenArch systemd-udevd[26543]: inotify_add_watch(9, /dev/sdb1, 10) failed: No such file or directory
Oct 21 10:49:06 ZenArch colord[1415]: /usr/lib/colord/colord-sane: error while loading shared libraries: libsane.so.1: cannot open shared object file: No such file or directory
Oct 21 10:49:06 ZenArch dbus[746]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service'
Oct 21 10:49:06 ZenArch colord[1415]: /usr/lib/colord/colord-sane: error while loading shared libraries: libsane.so.1: cannot open shared object file: No such file or directory
Oct 21 10:49:06 ZenArch colord[1415]: /usr/lib/colord/colord-sane: error while loading shared libraries: libsane.so.1: cannot open shared object file: No such file or directory
Oct 21 10:49:06 ZenArch systemd[1]: Starting Hostname Service...
-- Subject: Unit systemd-hostnamed.service has begun start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit systemd-hostnamed.service has begun starting up.
Oct 21 10:49:06 ZenArch udisksd[1778]: Unmounted /dev/sdb1 on behalf of uid 1000
Oct 21 10:49:06 ZenArch gnome-shell[17701]: JS LOG: error: Ejecting drive '31 GB Volume' failed:: Unable to find block device for drive
Oct 21 10:49:06 ZenArch dbus[746]: [system] Successfully activated service 'org.freedesktop.hostname1'
Oct 21 10:49:06 ZenArch systemd[1]: Started Hostname Service.
-- Subject: Unit systemd-hostnamed.service has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit systemd-hostnamed.service has finished starting up.
--
-- The start-up result is done.
Oct 21 10:52:11 ZenArch org.gnome.Shell.desktop[17701]: Window manager warning: last_user_time (47380208) is greater than comparison timestamp (47380205). This most likely represents a buggy client sending inaccu
Oct 21 10:52:11 ZenArch org.gnome.Shell.desktop[17701]: Window manager warning: 0x100000a (glances) appears to be one of the offending windows with a timestamp of 47380208. Working around...
Oct 21 10:52:11 ZenArch gnome-shell[17701]: JS LOG: pushModal: invocation of begin_modal failed
Oct 21 10:56:13 ZenArch wpa_supplicant[1073]: wlp1s0: CTRL-EVENT-DISCONNECTED bssid=d4:61:2e:13:bb:79 reason=4 locally_generated=1
Oct 21 10:56:13 ZenArch NetworkManager[825]: <warn> [1477022173.0706] sup-iface[0x2291ec0,wlp1s0]: connection disconnected (reason -4)
Oct 21 10:56:13 ZenArch NetworkManager[825]: <info> [1477022173.0974] device (wlp1s0): supplicant interface state: completed -> disconnected
Oct 21 10:56:13 ZenArch NetworkManager[825]: <info> [1477022173.1758] device (wlp1s0): supplicant interface state: disconnected -> scanning
Oct 21 10:56:24 ZenArch wpa_supplicant[1073]: wlp1s0: SME: Trying to authenticate with d4:61:2e:13:bb:79 (SSID='Aurora-BB79' freq=2412 MHz)
Oct 21 10:56:24 ZenArch kernel: wlp1s0: authenticate with d4:61:2e:13:bb:79
Oct 21 10:56:24 ZenArch NetworkManager[825]: <info> [1477022184.6281] device (wlp1s0): supplicant interface state: scanning -> authenticating
Oct 21 10:56:24 ZenArch kernel: wlp1s0: send auth to d4:61:2e:13:bb:79 (try 1/3)
Oct 21 10:56:24 ZenArch wpa_supplicant[1073]: wlp1s0: Trying to associate with d4:61:2e:13:bb:79 (SSID='Aurora-BB79' freq=2412 MHz)
Oct 21 10:56:24 ZenArch kernel: wlp1s0: authenticated
Oct 21 10:56:24 ZenArch kernel: wlp1s0: associate with d4:61:2e:13:bb:79 (try 1/3)
Oct 21 10:56:24 ZenArch NetworkManager[825]: <info> [1477022184.7030] device (wlp1s0): supplicant interface state: authenticating -> associating
Oct 21 10:56:24 ZenArch kernel: wlp1s0: associate with d4:61:2e:13:bb:79 (try 2/3)
Oct 21 10:56:24 ZenArch kernel: wlp1s0: RX AssocResp from d4:61:2e:13:bb:79 (capab=0x411 status=0 aid=1)
Oct 21 10:56:24 ZenArch wpa_supplicant[1073]: wlp1s0: Associated with d4:61:2e:13:bb:79
Oct 21 10:56:24 ZenArch wpa_supplicant[1073]: wlp1s0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Oct 21 10:56:24 ZenArch kernel: wlp1s0: associated
Oct 21 10:56:24 ZenArch NetworkManager[825]: <info> [1477022184.9724] device (wlp1s0): supplicant interface state: associating -> 4-way handshake
Oct 21 10:56:25 ZenArch wpa_supplicant[1073]: wlp1s0: WPA: Key negotiation completed with d4:61:2e:13:bb:79 [PTK=CCMP GTK=TKIP]
Oct 21 10:56:25 ZenArch wpa_supplicant[1073]: wlp1s0: CTRL-EVENT-CONNECTED - Connection to d4:61:2e:13:bb:79 completed [id=0 id_str=]
Oct 21 10:56:25 ZenArch NetworkManager[825]: <info> [1477022185.0189] device (wlp1s0): supplicant interface state: 4-way handshake -> completedAny suggestions or ideas what to do? Can this be kernel or hardware or maybe btrfs causing problems?
EDIT0: Just tried to copy the very same test batch from my home folder to the same usb drive using Fedora 24 live usb and the iowait is between 19-24 in an average. No issues at all.
EDIT1: Booted back to Arch and disabled the swap and tried the same process again. The iowait is still high, but the cpu usage doesn't go up and the system doesn't hang so by the look of it btrfs does cause the issue when the swap is on. The swap partition is also btrfs.
Last edited by nooke4000 (2016-10-21 04:44:10)
Offline
Pages: 1