[opensuse] Strange disk activity
Hi, I noticed in the graph of disk activity in GKrellM that there was some constant but intermittent activity on /dev/sda. Like this: __|__|__|__|__|__|__|__|__|__|__|__|__|__| It suddenly occurred to me that with GKrellM one can display a graph per partition! So I activated graphs for each one in /dev/sda and found the culprit: /dev/sda7. What do I have there? Well, nothing: Telcontar:~ # mount | grep sda7 /dev/sda7 on /other/test_a1 type reiserfs (rw,relatime,lazytime, user_xattr,acl) Telcontar:~ # It is a test partition of another system, nothing is active there: Telcontar:~ # cat /other/test_a1/etc/os-release NAME=openSUSE VERSION = 12.1 (Asparagus) VERSION_ID="12.1" PRETTY_NAME="openSUSE 12.1 (Asparagus) (x86_64)" ID=opensuse Telcontar:~ # I umounted it and the activity disappeared. Mounted it again and it kept silent. What was it? How can I find out the next time what is reading there? I see a similar intermitent activity on other partitions of disk /dev/sdc, on these partitions: /dev/sdc6 /dev/sdc7 /dev/sdc12 /dev/sdc14 /dev/sdc17 Telcontar:~ # mount | grep "sdc6\|sdc7\|sdc12\|sdc14\|sdc17" /dev/sdc17 on /home type ext4 (rw,relatime,data=ordered) /dev/sdc14 on /data/homedvl type reiserfs (rw,relatime,lazytime, user_xattr,acl) /dev/sdc7 on /usr/local type reiserfs (rw,relatime,lazytime, user_xattr,acl) /dev/sdc12 on /usr/gamedata type reiserfs (rw,relatime,lazytime, user_xattr,acl) /dev/sdc6 on /usr/src type reiserfs (rw,relatime,lazytime, user_xattr,acl) Telcontar:~ # So yes, it affects most of my reiserfs partitions (/var/spool/news is not affected). What is going on? -- Cheers / Saludos, Carlos E. R. (from 42.2 x86_64 "Malachite" at Telcontar)
On 09/26/2017 01:22 PM, Carlos E. R. wrote:
I noticed in the graph of disk activity in GKrellM that there was some constant but intermittent activity on /dev/sda. Like this:
__|__|__|__|__|__|__|__|__|__|__|__|__|__|
It suddenly occurred to me that with GKrellM one can display a graph per partition! So I activated graphs for each one in /dev/sda and found the culprit: /dev/sda7.
What do I have there? Well, nothing:
Telcontar:~ # mount | grep sda7 /dev/sda7 on /other/test_a1 type reiserfs (rw,relatime,lazytime, user_xattr,acl) Telcontar:~ #
Something like $ lsof /other/test_a1 when it is occurring? Or with the -/+r option to repeatedly probe for open files? Just a stab at it. -- David C. Rankin, J.D.,P.E.
On 2017-09-27 00:32, David C. Rankin wrote:
On 09/26/2017 01:22 PM, Carlos E. R. wrote:
I noticed in the graph of disk activity in GKrellM that there was some constant but intermittent activity on /dev/sda. Like this:
__|__|__|__|__|__|__|__|__|__|__|__|__|__|
It suddenly occurred to me that with GKrellM one can display a graph per partition! So I activated graphs for each one in /dev/sda and found the culprit: /dev/sda7.
What do I have there? Well, nothing:
Telcontar:~ # mount | grep sda7 /dev/sda7 on /other/test_a1 type reiserfs (rw,relatime,lazytime, user_xattr,acl) Telcontar:~ #
Something like
$ lsof /other/test_a1
when it is occurring? Or with the -/+r option to repeatedly probe for open files?
Just a stab at it.
If there was something opened the "umount" would have failed. And as I see the same activity in all the reiserfs mounts, except the one that is in actual use, it has to be something "internal". -- Cheers / Saludos, Carlos E. R. (from 42.2 x86_64 "Malachite" at Telcontar)
On 2017-09-27 05:22, Andrei Borzenkov wrote:
26.09.2017 21:22, Carlos E. R. пишет:
I umounted it and the activity disappeared. Mounted it again and it kept silent. What was it? How can I find out the next time what is reading there?
Try blktrace, it will show actual requests and where they are originated from.
Ah, thanks, I'l have to study it. One interesting thing is that the pulses happen simultaneously on all reiserfs partitions. Quick try: Telcontar:~ # blktrace -d /dev/sda7 -o blktrace.log ^C=== sda7 === CPU 0: 109 events, 6 KiB data CPU 1: 0 events, 0 KiB data CPU 2: 0 events, 0 KiB data CPU 3: 1 events, 1 KiB data Total: 110 events (dropped 0), 6 KiB data Telcontar:~ # Telcontar:~ # l blktrace.log.blktrace.* -rw-r--r-- 1 root root 5258 Sep 27 16:24 blktrace.log.blktrace.0 -rw-r--r-- 1 root root 0 Sep 27 16:24 blktrace.log.blktrace.1 -rw-r--r-- 1 root root 0 Sep 27 16:24 blktrace.log.blktrace.2 -rw-r--r-- 1 root root 56 Sep 27 16:24 blktrace.log.blktrace.3 Telcontar:~ # But the files are binary. Ah, needs "blkparse". I'm not able to understand them, I'll post them here: blktrace.log.blktrace.0 +++----------- 8,0 0 1 0.000000000 19276 A W 79768880 + 8 <- (8,7) 38192 8,7 0 2 0.000001578 19276 Q W 79768880 + 8 [kworker/0:0] 8,7 0 3 0.000006964 19276 G W 79768880 + 8 [kworker/0:0] 8,7 0 4 0.000008113 19276 I W 79768880 + 8 [kworker/0:0] 8,7 0 0 0.000010184 0 m N cfq1113A / insert_request 8,7 0 0 0.000013194 0 m N cfq1113A / slice expired t=0 8,7 0 0 0.000014643 0 m N / served: vt=687971963125760 min_vt=687808123125760 8,7 0 0 0.000015759 0 m N cfq1113A / sl_used=40000000 disp=1 charge=40000000 iops=0 sect=16 8,7 0 0 0.000017111 0 m N cfq workload slice:40000000 8,7 0 0 0.000017991 0 m N cfq1113A / set_active wl_class:0 wl_type:0 8,7 0 0 0.000019206 0 m N cfq1113A / Not idling. st->count:1 8,7 0 0 0.000019984 0 m N cfq1113A / dispatch_insert 8,7 0 0 0.000021029 0 m N cfq1113A / dispatched a request 8,7 0 0 0.000021690 0 m N cfq1113A / activate rq, drv=1 8,7 0 5 0.000022052 19276 D W 79768880 + 8 [kworker/0:0] 8,0 0 6 0.000076844 19276 A W 79768888 + 8 <- (8,7) 38200 8,7 0 7 0.000077089 19276 Q W 79768888 + 8 [kworker/0:0] 8,7 0 8 0.000078089 19276 G W 79768888 + 8 [kworker/0:0] 8,7 0 9 0.000078370 19276 I W 79768888 + 8 [kworker/0:0] 8,7 0 0 0.000079103 0 m N cfq1113A / insert_request 8,7 0 0 0.000080058 0 m N cfq1113A / Not idling. st->count:1 8,7 0 0 0.000080509 0 m N cfq1113A / dispatch_insert 8,7 0 0 0.000081156 0 m N cfq1113A / dispatched a request 8,7 0 0 0.000081638 0 m N cfq1113A / activate rq, drv=2 8,7 0 10 0.000081769 19276 D W 79768888 + 8 [kworker/0:0] 8,7 0 11 0.000262263 6308 C W 79768880 + 8 [0] 8,7 0 0 0.000270255 0 m N cfq1113A / complete rqnoidle 0 8,7 0 0 0.000271644 0 m N cfq1113A / set_slice=40000000 8,7 0 12 0.000517065 6308 C W 79768888 + 8 [0] 8,7 0 0 0.000519988 0 m N cfq1113A / complete rqnoidle 0 8,7 0 0 0.000520527 0 m N cfq schedule dispatch 8,0 0 13 0.000525638 19276 A FWFS 79768896 + 8 <- (8,7) 38208 8,7 0 14 0.000525928 19276 Q FWFS 79768896 + 8 [kworker/0:0] 8,7 0 15 0.000526787 19276 G FWFS 79768896 + 8 [kworker/0:0] 8,7 0 16 0.000527143 19276 I FWFS 79768896 + 8 [kworker/0:0] 8,7 0 17 0.022054231 0 D WS 79768896 + 8 [swapper/0] 8,7 0 18 0.022315311 0 C WS 79768896 + 8 [0] 8,7 0 19 0.047086271 0 C WS 79768896 [0] 8,0 0 20 5.007980536 19276 A W 79768904 + 8 <- (8,7) 38216 8,7 0 21 5.007982714 19276 Q W 79768904 + 8 [kworker/0:0] 8,7 0 22 5.007989136 19276 G W 79768904 + 8 [kworker/0:0] 8,7 0 23 5.007990743 19276 I W 79768904 + 8 [kworker/0:0] 8,7 0 0 5.007993185 0 m N cfq1113A / insert_request 8,7 0 0 5.007996761 0 m N cfq1113A / slice expired t=0 8,7 0 0 5.007998562 0 m N / served: vt=688135803125760 min_vt=687971963125760 8,7 0 0 5.008000196 0 m N cfq1113A / sl_used=40000000 disp=2 charge=40000000 iops=0 sect=16 8,7 0 0 5.008001414 0 m N cfq workload slice:40000000 8,7 0 0 5.008002659 0 m N cfq1113A / set_active wl_class:0 wl_type:0 8,7 0 0 5.008003889 0 m N cfq1113A / Not idling. st->count:1 8,7 0 0 5.008004942 0 m N cfq1113A / dispatch_insert 8,7 0 0 5.008006555 0 m N cfq1113A / dispatched a request 8,7 0 0 5.008007498 0 m N cfq1113A / activate rq, drv=1 8,7 0 24 5.008007875 19276 D W 79768904 + 8 [kworker/0:0] 8,0 0 25 5.008064306 19276 A W 79768912 + 8 <- (8,7) 38224 8,7 0 26 5.008064624 19276 Q W 79768912 + 8 [kworker/0:0] 8,7 0 27 5.008065872 19276 G W 79768912 + 8 [kworker/0:0] 8,7 0 28 5.008066240 19276 I W 79768912 + 8 [kworker/0:0] 8,7 0 0 5.008067257 0 m N cfq1113A / insert_request 8,7 0 0 5.008068541 0 m N cfq1113A / Not idling. st->count:1 8,7 0 0 5.008069232 0 m N cfq1113A / dispatch_insert 8,7 0 0 5.008070121 0 m N cfq1113A / dispatched a request 8,7 0 0 5.008070815 0 m N cfq1113A / activate rq, drv=2 8,7 0 29 5.008071013 19276 D W 79768912 + 8 [kworker/0:0] 8,7 0 30 5.008251515 0 C W 79768904 + 8 [0] 8,7 0 0 5.008256761 0 m N cfq1113A / complete rqnoidle 0 8,7 0 0 5.008258365 0 m N cfq1113A / set_slice=40000000 8,7 0 31 5.008495990 0 C W 79768912 + 8 [0] 8,7 0 0 5.008499311 0 m N cfq1113A / complete rqnoidle 0 8,7 0 0 5.008500062 0 m N cfq schedule dispatch 8,0 0 32 5.008509082 19276 A FWFS 79768920 + 8 <- (8,7) 38232 8,7 0 33 5.008509480 19276 Q FWFS 79768920 + 8 [kworker/0:0] 8,7 0 34 5.008510545 19276 G FWFS 79768920 + 8 [kworker/0:0] 8,7 0 35 5.008511066 19276 I FWFS 79768920 + 8 [kworker/0:0] 8,7 0 36 5.031424140 4788 D WS 79768920 + 8 [firefox] 8,7 0 37 5.031686644 0 C WS 79768920 + 8 [0] 8,7 0 38 5.056455770 0 C WS 79768920 [0] CPU0 (blktrace.log): Reads Queued: 0, 0KiB Writes Queued: 6, 24KiB Read Dispatches: 0, 0KiB Write Dispatches: 6, 24KiB Reads Requeued: 0 Writes Requeued: 0 Reads Completed: 0, 0KiB Writes Completed: 8, 24KiB Read Merges: 0, 0KiB Write Merges: 0, 0KiB Read depth: 0 Write depth: 2 IO unplugs: 0 Timer unplugs: 0 Throughput (R/W): 0KiB/s / 4KiB/s Events (blktrace.log): 76 entries Skips: 0 forward (0 - 0.0%) Input file blktrace.log.blktrace.0 added Input file blktrace.log.blktrace.3 added -----------++- blktrace.log.blktrace.3 +++----------- 8,0 0 1 0.000000000 19276 A W 79768880 + 8 <- (8,7) 38192 8,7 0 2 0.000001578 19276 Q W 79768880 + 8 [kworker/0:0] 8,7 0 3 0.000006964 19276 G W 79768880 + 8 [kworker/0:0] 8,7 0 4 0.000008113 19276 I W 79768880 + 8 [kworker/0:0] 8,7 0 0 0.000010184 0 m N cfq1113A / insert_request 8,7 0 0 0.000013194 0 m N cfq1113A / slice expired t=0 8,7 0 0 0.000014643 0 m N / served: vt=687971963125760 min_vt=687808123125760 8,7 0 0 0.000015759 0 m N cfq1113A / sl_used=40000000 disp=1 charge=40000000 iops=0 sect=16 8,7 0 0 0.000017111 0 m N cfq workload slice:40000000 8,7 0 0 0.000017991 0 m N cfq1113A / set_active wl_class:0 wl_type:0 8,7 0 0 0.000019206 0 m N cfq1113A / Not idling. st->count:1 8,7 0 0 0.000019984 0 m N cfq1113A / dispatch_insert 8,7 0 0 0.000021029 0 m N cfq1113A / dispatched a request 8,7 0 0 0.000021690 0 m N cfq1113A / activate rq, drv=1 8,7 0 5 0.000022052 19276 D W 79768880 + 8 [kworker/0:0] 8,0 0 6 0.000076844 19276 A W 79768888 + 8 <- (8,7) 38200 8,7 0 7 0.000077089 19276 Q W 79768888 + 8 [kworker/0:0] 8,7 0 8 0.000078089 19276 G W 79768888 + 8 [kworker/0:0] 8,7 0 9 0.000078370 19276 I W 79768888 + 8 [kworker/0:0] 8,7 0 0 0.000079103 0 m N cfq1113A / insert_request 8,7 0 0 0.000080058 0 m N cfq1113A / Not idling. st->count:1 8,7 0 0 0.000080509 0 m N cfq1113A / dispatch_insert 8,7 0 0 0.000081156 0 m N cfq1113A / dispatched a request 8,7 0 0 0.000081638 0 m N cfq1113A / activate rq, drv=2 8,7 0 10 0.000081769 19276 D W 79768888 + 8 [kworker/0:0] 8,7 0 11 0.000262263 6308 C W 79768880 + 8 [0] 8,7 0 0 0.000270255 0 m N cfq1113A / complete rqnoidle 0 8,7 0 0 0.000271644 0 m N cfq1113A / set_slice=40000000 8,7 0 12 0.000517065 6308 C W 79768888 + 8 [0] 8,7 0 0 0.000519988 0 m N cfq1113A / complete rqnoidle 0 8,7 0 0 0.000520527 0 m N cfq schedule dispatch 8,0 0 13 0.000525638 19276 A FWFS 79768896 + 8 <- (8,7) 38208 8,7 0 14 0.000525928 19276 Q FWFS 79768896 + 8 [kworker/0:0] 8,7 0 15 0.000526787 19276 G FWFS 79768896 + 8 [kworker/0:0] 8,7 0 16 0.000527143 19276 I FWFS 79768896 + 8 [kworker/0:0] 8,7 0 17 0.022054231 0 D WS 79768896 + 8 [swapper/0] 8,7 0 18 0.022315311 0 C WS 79768896 + 8 [0] 8,7 0 19 0.047086271 0 C WS 79768896 [0] 8,0 0 20 5.007980536 19276 A W 79768904 + 8 <- (8,7) 38216 8,7 0 21 5.007982714 19276 Q W 79768904 + 8 [kworker/0:0] 8,7 0 22 5.007989136 19276 G W 79768904 + 8 [kworker/0:0] 8,7 0 23 5.007990743 19276 I W 79768904 + 8 [kworker/0:0] 8,7 0 0 5.007993185 0 m N cfq1113A / insert_request 8,7 0 0 5.007996761 0 m N cfq1113A / slice expired t=0 8,7 0 0 5.007998562 0 m N / served: vt=688135803125760 min_vt=687971963125760 8,7 0 0 5.008000196 0 m N cfq1113A / sl_used=40000000 disp=2 charge=40000000 iops=0 sect=16 8,7 0 0 5.008001414 0 m N cfq workload slice:40000000 8,7 0 0 5.008002659 0 m N cfq1113A / set_active wl_class:0 wl_type:0 8,7 0 0 5.008003889 0 m N cfq1113A / Not idling. st->count:1 8,7 0 0 5.008004942 0 m N cfq1113A / dispatch_insert 8,7 0 0 5.008006555 0 m N cfq1113A / dispatched a request 8,7 0 0 5.008007498 0 m N cfq1113A / activate rq, drv=1 8,7 0 24 5.008007875 19276 D W 79768904 + 8 [kworker/0:0] 8,0 0 25 5.008064306 19276 A W 79768912 + 8 <- (8,7) 38224 8,7 0 26 5.008064624 19276 Q W 79768912 + 8 [kworker/0:0] 8,7 0 27 5.008065872 19276 G W 79768912 + 8 [kworker/0:0] 8,7 0 28 5.008066240 19276 I W 79768912 + 8 [kworker/0:0] 8,7 0 0 5.008067257 0 m N cfq1113A / insert_request 8,7 0 0 5.008068541 0 m N cfq1113A / Not idling. st->count:1 8,7 0 0 5.008069232 0 m N cfq1113A / dispatch_insert 8,7 0 0 5.008070121 0 m N cfq1113A / dispatched a request 8,7 0 0 5.008070815 0 m N cfq1113A / activate rq, drv=2 8,7 0 29 5.008071013 19276 D W 79768912 + 8 [kworker/0:0] 8,7 0 30 5.008251515 0 C W 79768904 + 8 [0] 8,7 0 0 5.008256761 0 m N cfq1113A / complete rqnoidle 0 8,7 0 0 5.008258365 0 m N cfq1113A / set_slice=40000000 8,7 0 31 5.008495990 0 C W 79768912 + 8 [0] 8,7 0 0 5.008499311 0 m N cfq1113A / complete rqnoidle 0 8,7 0 0 5.008500062 0 m N cfq schedule dispatch 8,0 0 32 5.008509082 19276 A FWFS 79768920 + 8 <- (8,7) 38232 8,7 0 33 5.008509480 19276 Q FWFS 79768920 + 8 [kworker/0:0] 8,7 0 34 5.008510545 19276 G FWFS 79768920 + 8 [kworker/0:0] 8,7 0 35 5.008511066 19276 I FWFS 79768920 + 8 [kworker/0:0] 8,7 0 36 5.031424140 4788 D WS 79768920 + 8 [firefox] 8,7 0 37 5.031686644 0 C WS 79768920 + 8 [0] 8,7 0 38 5.056455770 0 C WS 79768920 [0] CPU0 (blktrace.log): Reads Queued: 0, 0KiB Writes Queued: 6, 24KiB Read Dispatches: 0, 0KiB Write Dispatches: 6, 24KiB Reads Requeued: 0 Writes Requeued: 0 Reads Completed: 0, 0KiB Writes Completed: 8, 24KiB Read Merges: 0, 0KiB Write Merges: 0, 0KiB Read depth: 0 Write depth: 2 IO unplugs: 0 Timer unplugs: 0 Throughput (R/W): 0KiB/s / 4KiB/s Events (blktrace.log): 76 entries Skips: 0 forward (0 - 0.0%) Input file blktrace.log.blktrace.0 added Input file blktrace.log.blktrace.3 added -----------++- -- Cheers / Saludos, Carlos E. R. (from 42.2 x86_64 "Malachite" at Telcontar)
participants (3)
-
Andrei Borzenkov -
Carlos E. R. -
David C. Rankin