Script 'mail_helper' called by obssrc Hello community, here is the log from the commit of package blktrace for openSUSE:Factory checked in at 2021-10-16 22:47:14 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ Comparing /work/SRC/openSUSE:Factory/blktrace (Old) and /work/SRC/openSUSE:Factory/.blktrace.new.1890 (New) ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
Package is "blktrace" Sat Oct 16 22:47:14 2021 rev:36 rq:925611 version:1.3.0+git.20210628 Changes: -------- --- /work/SRC/openSUSE:Factory/blktrace/blktrace.changes 2018-06-08 23:15:09.756720392 +0200 +++ /work/SRC/openSUSE:Factory/.blktrace.new.1890/blktrace.changes 2021-10-16 22:47:49.600701345 +0200 @@ -1,0 +2,20 @@ +Mon Oct 11 13:08:42 UTC 2021 - dd...@suse.com + +- Update to version 1.3.0+git.20210628: + * blktrace: exit directly when nthreads_running != ncpus in run_tracers() + * blktrace 1.3.0 + * blkparse: Print time when trace was started + * blktrace: inclusive terminology + * blkparse: Print PID information for TN_MESSAGE events + * iowatcher: Handle cgroup information + * iowatcher: Use blktrace_api.h + * blkparse: Handle cgroup information + * blkparse: Fix up the sector and length of split completions + * blkparse: Initialize and test for undefined request tracking timestamps + +------------------------------------------------------------------- +Mon Oct 11 11:43:50 UTC 2021 - David Disseldorp <dd...@suse.com> + +- UsrMerge: relocate blktrace, blkparse and btrace (bsc#1191056) + +------------------------------------------------------------------- Old: ---- blktrace-1.2.0+git.20180516.tar.xz New: ---- blktrace-1.3.0+git.20210628.tar.xz ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ Other differences: ------------------ ++++++ blktrace.spec ++++++ --- /var/tmp/diff_new_pack.UQdZRT/_old 2021-10-16 22:47:50.112701777 +0200 +++ /var/tmp/diff_new_pack.UQdZRT/_new 2021-10-16 22:47:50.116701780 +0200 @@ -1,7 +1,7 @@ # # spec file for package blktrace # -# Copyright (c) 2018 SUSE LINUX GmbH, Nuernberg, Germany. +# Copyright (c) 2021 SUSE LLC # # All modifications and additions to the file contributed by third parties # remain the property of their copyright owners, unless otherwise agreed @@ -12,18 +12,18 @@ # license that conforms to the Open Source Definition (Version 1.9) # published by the Open Source Initiative. -# Please submit bugfixes or comments via http://bugs.opensuse.org/ +# Please submit bugfixes or comments via https://bugs.opensuse.org/ # %{!?_without_docs: %global with_docs 1} Name: blktrace -Version: 1.2.0+git.20180516 +Version: 1.3.0+git.20210628 Release: 0 Summary: Block IO tracer -License: GPL-2.0 +License: GPL-2.0-only Group: Development/Tools/Other -Url: http://git.kernel.dk/?p=blktrace.git;a=summary +URL: http://git.kernel.dk/?p=blktrace.git;a=summary Source0: %{name}-%{version}.tar.xz Patch0: blkparse-track-smallest-sequence-read-per-device.patch BuildRequires: gcc @@ -64,17 +64,13 @@ %install make DESTDIR=%{buildroot} prefix=%{_prefix} mandir=%{_mandir} install -# move blktrace to /bin (bug #300186) -mkdir -p %{buildroot}/bin -mv %{buildroot}%{_bindir}/{blktrace,blkparse,btrace} \ - %{buildroot}/bin %files %defattr(-,root,root) %doc README %{?with_docs: doc/blktrace.pdf btreplay/doc/btreplay.pdf btt/doc/btt.pdf} -/bin/blktrace -/bin/blkparse -/bin/btrace +%{_bindir}/blktrace +%{_bindir}/blkparse +%{_bindir}/btrace %{_bindir}/blkrawverify %{_bindir}/bno_plot.py %{_bindir}/btt ++++++ _service ++++++ --- /var/tmp/diff_new_pack.UQdZRT/_old 2021-10-16 22:47:50.148701807 +0200 +++ /var/tmp/diff_new_pack.UQdZRT/_new 2021-10-16 22:47:50.152701811 +0200 @@ -1,10 +1,10 @@ <services> <service mode="disabled" name="tar_scm"> - <param name="url">git://git.kernel.dk/blktrace.git</param> + <param name="url">https://git.kernel.dk/blktrace.git</param> <param name="scm">git</param> <param name="changesgenerate">enable</param> <param name="filename">blktrace</param> - <param name="versionformat">1.2.0+git.%cd</param> + <param name="versionformat">1.3.0+git.%cd</param> </service> <service mode="disabled" name="recompress"> <param name="file">*.tar</param> ++++++ _servicedata ++++++ --- /var/tmp/diff_new_pack.UQdZRT/_old 2021-10-16 22:47:50.176701831 +0200 +++ /var/tmp/diff_new_pack.UQdZRT/_new 2021-10-16 22:47:50.176701831 +0200 @@ -1,4 +1,6 @@ <servicedata> <service name="tar_scm"> <param name="url">git://git.kernel.dk/blktrace.git</param> - <param name="changesrevision">70d5ca2d5f3d6b97c11c641b7e0c5836983219a0</param></service></servicedata> \ No newline at end of file + <param name="changesrevision">70d5ca2d5f3d6b97c11c641b7e0c5836983219a0</param></service><service name="tar_scm"> + <param name="url">https://git.kernel.dk/blktrace.git</param> + <param name="changesrevision">3a1b1366d30375cdb0f5b299df4edda0c8ba3bcc</param></service></servicedata> \ No newline at end of file ++++++ blktrace-1.2.0+git.20180516.tar.xz -> blktrace-1.3.0+git.20210628.tar.xz ++++++ diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn' '--exclude=.svnignore' old/blktrace-1.2.0+git.20180516/Makefile new/blktrace-1.3.0+git.20210628/Makefile --- old/blktrace-1.2.0+git.20180516/Makefile 2018-05-16 21:09:58.000000000 +0200 +++ new/blktrace-1.3.0+git.20210628/Makefile 2021-06-28 21:41:32.000000000 +0200 @@ -14,7 +14,7 @@ # We always descend into subdirs because they contain their own dependency # information which we don't track in this top level Makefile. -$(SUBDIRS): +$(SUBDIRS): $(PROGS) $(MAKE) -C $@ .PHONY: $(SUBDIRS) diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn' '--exclude=.svnignore' old/blktrace-1.2.0+git.20180516/blkparse.c new/blktrace-1.3.0+git.20210628/blkparse.c --- old/blktrace-1.2.0+git.20180516/blkparse.c 2018-05-16 21:09:58.000000000 +0200 +++ new/blktrace-1.3.0+git.20210628/blkparse.c 2021-06-28 21:41:32.000000000 +0200 @@ -25,18 +25,20 @@ #include <stdio.h> #include <fcntl.h> #include <stdlib.h> +#include <stdarg.h> #include <string.h> #include <getopt.h> #include <errno.h> #include <signal.h> #include <locale.h> #include <libgen.h> +#include <time.h> #include "blktrace.h" #include "rbtree.h" #include "jhash.h" -static char blkparse_version[] = "1.2.0"; +static char blkparse_version[] = "1.3.0"; struct skip_info { unsigned long start, end; @@ -100,6 +102,19 @@ #define PPI_HASH_SHIFT (8) #define PPI_HASH_SIZE (1 << PPI_HASH_SHIFT) #define PPI_HASH_MASK (PPI_HASH_SIZE - 1) + +enum { + SORT_PROG_EVENT_N, /* Program Name */ + SORT_PROG_EVENT_QKB, /* KB: Queued read and write */ + SORT_PROG_EVENT_RKB, /* KB: Queued Read */ + SORT_PROG_EVENT_WKB, /* KB: Queued Write */ + SORT_PROG_EVENT_CKB, /* KB: Complete */ + SORT_PROG_EVENT_QIO, /* IO: Queued read and write */ + SORT_PROG_EVENT_RIO, /* IO: Queued Read */ + SORT_PROG_EVENT_WIO, /* IO: Queued Write */ + SORT_PROG_EVENT_CIO, /* IO: Complete */ +}; + static struct per_process_info *ppi_hash_table[PPI_HASH_SIZE]; static struct per_process_info *ppi_list; static int ppi_list_entries; @@ -190,6 +205,12 @@ .val = 's' }, { + .name = "sort-program-stats", + .has_arg = required_argument, + .flag = NULL, + .val = 'S' + }, + { .name = "track-ios", .has_arg = no_argument, .flag = NULL, @@ -242,17 +263,21 @@ /* * for tracking individual ios */ -struct io_track { - struct rb_node rb_node; - +struct io_track_req { struct process_pid_map *ppm; - __u64 sector; unsigned long long allocation_time; unsigned long long queue_time; unsigned long long dispatch_time; unsigned long long completion_time; }; +struct io_track { + struct rb_node rb_node; + struct io_track_req *req; + struct io_track *next; + __u64 sector; +}; + static int ndevices; static struct per_dev_info *devices; static char *get_dev_name(struct per_dev_info *, char *, int); @@ -269,6 +294,7 @@ static unsigned long read_sequence; static int per_process_stats; +static int per_process_stats_event = SORT_PROG_EVENT_N; static int per_device_and_cpu_stats = 1; static int track_ios; static int ppi_hash_by_pid = 1; @@ -306,6 +332,21 @@ #define CPU_IDX(cpu) ((cpu) / CPUS_PER_LONG) #define CPU_BIT(cpu) ((cpu) & (CPUS_PER_LONG - 1)) +static void io_warn_unless(struct blk_io_trace *t, int condition, + const char *fmt, ...) +{ + va_list ap; + + if (condition) + return; + va_start(ap, fmt); + printf("(%d,%d) request %llu + %u: ", + MAJOR(t->device), MINOR(t->device), + t->sector, t->bytes); + vfprintf(stderr, fmt, ap); + va_end(ap); +} + static void output_binary(void *buf, int len) { if (dump_binary) { @@ -577,7 +618,7 @@ void *payload = (caddr_t) bit + sizeof(*bit); __u32 two32[2]; - switch (bit->action) { + switch (bit->action & ~__BLK_TN_CGROUP) { case BLK_TN_PROCESS: add_ppm_hash(bit->pid, payload); break; @@ -603,16 +644,27 @@ case BLK_TN_MESSAGE: if (bit->pdu_len > 0) { char msg[bit->pdu_len+1]; + int len = bit->pdu_len; + char cgidstr[24]; - memcpy(msg, (char *)payload, bit->pdu_len); - msg[bit->pdu_len] = '\0'; + cgidstr[0] = 0; + if (bit->action & __BLK_TN_CGROUP) { + struct blk_io_cgroup_payload *cgid = payload; + + sprintf(cgidstr, "%x,%x ", cgid->ino, + cgid->gen); + payload += sizeof(struct blk_io_cgroup_payload); + len -= sizeof(struct blk_io_cgroup_payload); + } + memcpy(msg, (char *)payload, len); + msg[len] = '\0'; fprintf(ofp, - "%3d,%-3d %2d %8s %5d.%09lu %5u %2s %3s %s\n", + "%3d,%-3d %2d %8s %5d.%09lu %5u %s%2s %3s %s\n", MAJOR(bit->device), MINOR(bit->device), - bit->cpu, "0", (int) SECONDS(bit->time), - (unsigned long) NANO_SECONDS(bit->time), - 0, "m", "N", msg); + bit->cpu, "0", (int)SECONDS(bit->time), + (unsigned long)NANO_SECONDS(bit->time), + bit->pid, cgidstr, "m", "N", msg); } break; @@ -956,6 +1008,11 @@ return NULL; } +static inline struct io_track *first_iot(struct io_track_req *req) +{ + return (struct io_track *)(req + 1); +} + static struct io_track *find_track(struct per_dev_info *pdi, pid_t pid, __u64 sector) { @@ -963,10 +1020,19 @@ iot = __find_track(pdi, sector); if (!iot) { - iot = malloc(sizeof(*iot)); - iot->ppm = find_ppm(pid); - if (!iot->ppm) - iot->ppm = add_ppm_hash(pid, "unknown"); + struct io_track_req *req; + + req = malloc(sizeof(*req) + sizeof(*iot)); + req->ppm = find_ppm(pid); + if (!req->ppm) + req->ppm = add_ppm_hash(pid, "unknown"); + req->allocation_time = -1ULL; + req->queue_time = -1ULL; + req->dispatch_time = -1ULL; + req->completion_time = -1ULL; + iot = first_iot(req); + iot->req = req; + iot->next = NULL; iot->sector = sector; track_rb_insert(pdi, iot); } @@ -986,7 +1052,7 @@ if (!iot) { if (verbose) fprintf(stderr, "merge not found for (%d,%d): %llu\n", - MAJOR(pdi->dev), MINOR(pdi->dev), + MAJOR(t->device), MINOR(t->device), (unsigned long long) t->sector + t_sec(t)); return; } @@ -999,19 +1065,16 @@ static void log_track_getrq(struct per_dev_info *pdi, struct blk_io_trace *t) { struct io_track *iot; + struct io_track_req *req; if (!track_ios) return; iot = find_track(pdi, t->pid, t->sector); - iot->allocation_time = t->time; -} - -static inline int is_remapper(struct per_dev_info *pdi) -{ - int major = MAJOR(pdi->dev); - - return (major == 253 || major == 9); + req = iot->req; + io_warn_unless(t, req->allocation_time == -1ULL, + "confused about %s time", "allocation"); + req->allocation_time = t->time; } /* @@ -1021,14 +1084,34 @@ static void log_track_queue(struct per_dev_info *pdi, struct blk_io_trace *t) { struct io_track *iot; + struct io_track_req *req; if (!track_ios) return; - if (!is_remapper(pdi)) - return; iot = find_track(pdi, t->pid, t->sector); - iot->dispatch_time = t->time; + req = iot->req; + io_warn_unless(t, req->dispatch_time == -1ULL, + "confused about %s time", "dispatch"); + req->dispatch_time = t->time; +} + +static void log_track_split(struct per_dev_info *pdi, struct blk_io_trace *t) +{ + struct io_track *iot, *split; + + /* + * With a split request, the completion event will refer to the last + * part of the original request, but other events might refer to other + * parts. + */ + iot = find_track(pdi, t->pid, t->sector); + split = malloc(sizeof(*iot)); + split->req = iot->req; + split->next = iot->next; + iot->next = split; + split->sector = iot->sector + t_sec(t); + track_rb_insert(pdi, split); } /* @@ -1039,20 +1122,24 @@ { unsigned long long elapsed; struct io_track *iot; + struct io_track_req *req; if (!track_ios) return -1; iot = find_track(pdi, t->pid, t->sector); - iot->queue_time = t->time; + req = iot->req; + io_warn_unless(t, req->queue_time == -1ULL, + "confused about %s time", "queue"); + req->queue_time = t->time; - if (!iot->allocation_time) + if (req->allocation_time == -1ULL) return -1; - elapsed = iot->queue_time - iot->allocation_time; + elapsed = req->queue_time - req->allocation_time; if (per_process_stats) { - struct per_process_info *ppi = find_ppi(iot->ppm->pid); + struct per_process_info *ppi = find_ppi(req->ppm->pid); int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0; if (ppi && elapsed > ppi->longest_allocation_wait[w]) @@ -1068,8 +1155,9 @@ static unsigned long long log_track_issue(struct per_dev_info *pdi, struct blk_io_trace *t) { - unsigned long long elapsed; + unsigned long long elapsed = -1ULL; struct io_track *iot; + struct io_track_req *req; if (!track_ios) return -1; @@ -1080,16 +1168,20 @@ if (!iot) { if (verbose) fprintf(stderr, "issue not found for (%d,%d): %llu\n", - MAJOR(pdi->dev), MINOR(pdi->dev), + MAJOR(t->device), MINOR(t->device), (unsigned long long) t->sector); return -1; } - iot->dispatch_time = t->time; - elapsed = iot->dispatch_time - iot->queue_time; + req = iot->req; + io_warn_unless(t, req->dispatch_time == -1ULL, + "confused about %s time", "dispatch"); + req->dispatch_time = t->time; + if (req->queue_time != -1ULL) + elapsed = req->dispatch_time - req->queue_time; - if (per_process_stats) { - struct per_process_info *ppi = find_ppi(iot->ppm->pid); + if (elapsed != -1ULL && per_process_stats) { + struct per_process_info *ppi = find_ppi(req->ppm->pid); int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0; if (ppi && elapsed > ppi->longest_dispatch_wait[w]) @@ -1099,14 +1191,34 @@ return elapsed; } +static void fixup_complete(struct per_dev_info *pdi, struct blk_io_trace *t) +{ + struct io_track *iot; + __u64 start_sector; + + iot = __find_track(pdi, t->sector); + if (!iot) + return; + + /* + * When a split io completes, the sector and length of the completion + * refer to the last part of the original request. Fix the sector and + * length of the complete event to match the original request. + */ + start_sector = first_iot(iot->req)->sector; + t->bytes += (t->sector - start_sector) << 9; + t->sector = start_sector; +} + /* * return time between dispatch and complete */ static unsigned long long log_track_complete(struct per_dev_info *pdi, struct blk_io_trace *t) { - unsigned long long elapsed; - struct io_track *iot; + unsigned long long elapsed = -1ULL; + struct io_track *iot, *next; + struct io_track_req *req; if (!track_ios) return -1; @@ -1115,16 +1227,20 @@ if (!iot) { if (verbose) fprintf(stderr,"complete not found for (%d,%d): %llu\n", - MAJOR(pdi->dev), MINOR(pdi->dev), + MAJOR(t->device), MINOR(t->device), (unsigned long long) t->sector); return -1; } - iot->completion_time = t->time; - elapsed = iot->completion_time - iot->dispatch_time; + req = iot->req; + io_warn_unless(t, req->completion_time == -1ULL, + "confused about %s time", "completion"); + req->completion_time = t->time; + if (req->dispatch_time != -1ULL) + elapsed = req->completion_time - req->dispatch_time; - if (per_process_stats) { - struct per_process_info *ppi = find_ppi(iot->ppm->pid); + if (elapsed != -1ULL && per_process_stats) { + struct per_process_info *ppi = find_ppi(req->ppm->pid); int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0; if (ppi && elapsed > ppi->longest_completion_wait[w]) @@ -1134,8 +1250,13 @@ /* * kill the trace, we don't need it after completion */ - rb_erase(&iot->rb_node, &pdi->rb_track); - free(iot); + for (iot = first_iot(req); iot; iot = next) { + next = iot->next; + rb_erase(&iot->rb_node, &pdi->rb_track); + if (iot != first_iot(req)) + free(iot); + } + free(req); return elapsed; } @@ -1491,7 +1612,7 @@ struct per_cpu_info *pci) { int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0; - int act = t->action & 0xffff; + int act = (t->action & 0xffff) & ~__BLK_TA_CGROUP; switch (act) { case __BLK_TA_QUEUE: @@ -1540,7 +1661,7 @@ struct per_cpu_info *pci) { int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0; - int act = t->action & 0xffff; + int act = (t->action & 0xffff) & ~__BLK_TA_CGROUP; switch (act) { case __BLK_TA_QUEUE: @@ -1586,6 +1707,7 @@ case __BLK_TA_COMPLETE: if (pdi->cur_depth[w]) pdi->cur_depth[w]--; + fixup_complete(pdi, t); account_c(t, pci, w, t->bytes); log_complete(pdi, pci, t, "C"); break; @@ -1601,6 +1723,7 @@ log_unplug(pci, t, "UT"); break; case __BLK_TA_SPLIT: + log_track_split(pdi, t); log_split(pci, t, "X"); break; case __BLK_TA_BOUNCE: @@ -1623,7 +1746,7 @@ struct per_dev_info *pdi) { if (text_output) { - if (t->action == BLK_TN_MESSAGE) + if ((t->action & ~__BLK_TN_CGROUP) == BLK_TN_MESSAGE) handle_notify(t); else if (t->action & BLK_TC_ACT(BLK_TC_PC)) dump_trace_pc(t, pdi, pci); @@ -1638,7 +1761,7 @@ if (bin_output_msgs || !(t->action & BLK_TC_ACT(BLK_TC_NOTIFY) && - t->action == BLK_TN_MESSAGE)) + (t->action & ~__BLK_TN_CGROUP) == BLK_TN_MESSAGE)) output_binary(t, sizeof(*t) + t->pdu_len); } @@ -1758,6 +1881,88 @@ return res; } +static int ppi_event_compare(const void *p1, const void *p2) +{ + struct per_process_info *ppi1 = *((struct per_process_info **) p1); + struct per_process_info *ppi2 = *((struct per_process_info **) p2); + struct io_stats *ios1 = &ppi1->io_stats; + struct io_stats *ios2 = &ppi2->io_stats; + unsigned long io1, io2; + unsigned long long kb1,kb2; + int sort_by_kb = 1; + + io1 = io2 = 0; + kb1 = kb2 = 0; + + switch (per_process_stats_event) { + case SORT_PROG_EVENT_QKB: /* KB: Queued read and write */ + kb1 = ios1->qwrite_kb + (ios1->qwrite_b>>10) + + ios1->qread_kb + (ios1->qread_b>>10); + kb2 = ios2->qwrite_kb + (ios2->qwrite_b>>10) + + ios2->qread_kb + (ios2->qread_b>>10); + break; + case SORT_PROG_EVENT_RKB: /* KB: Queued Read */ + kb1 = ios1->qread_kb + (ios1->qread_b>>10); + kb2 = ios2->qread_kb + (ios2->qread_b>>10); + break; + case SORT_PROG_EVENT_WKB: /* KB: Queued Write */ + kb1 = ios1->qwrite_kb + (ios1->qwrite_b>>10); + kb2 = ios2->qwrite_kb + (ios2->qwrite_b>>10); + break; + case SORT_PROG_EVENT_CKB: /* KB: Complete */ + kb1 = ios1->cwrite_kb + (ios1->cwrite_b>>10) + + ios1->cread_kb + (ios1->cread_b>>10); + kb2 = ios2->cwrite_kb + (ios2->cwrite_b>>10) + + ios2->cread_kb + (ios2->cread_b>>10); + break; + case SORT_PROG_EVENT_QIO: /* IO: Queued read and write */ + sort_by_kb = 0; + io1 = ios1->qreads + ios1->qwrites; + io2 = ios2->qreads + ios2->qwrites; + break; + case SORT_PROG_EVENT_RIO: /* IO: Queued Read */ + sort_by_kb = 0; + io1 = ios1->qreads; + io2 = ios2->qreads; + break; + case SORT_PROG_EVENT_WIO: /* IO: Queued Write */ + sort_by_kb = 0; + io1 = ios1->qwrites; + io2 = ios2->qwrites; + break; + case SORT_PROG_EVENT_CIO: /* IO: Complete */ + sort_by_kb = 0; + io1 = ios1->creads + ios1->cwrites; + io2 = ios2->creads + ios2->cwrites; + break; + } + + + /* compare kb */ + if (sort_by_kb) { + if (kb1 > kb2) + return 1; + else if (kb1 == kb2) + return 0; + return -1; + } + + /* compare io */ + if (io1 > io2) + return 1; + else if (io1 == io2) + return 0; + return -1; +} + +static int ppi_compare(const void *p1, const void *p2) +{ + if (per_process_stats_event == SORT_PROG_EVENT_N) + return ppi_name_compare(p1, p2); + + return ppi_event_compare(p1, p2); +} + static void sort_process_list(void) { struct per_process_info **ppis; @@ -1772,7 +1977,7 @@ ppi = ppi->list_next; } - qsort(ppis, ppi_list_entries, sizeof(ppi), ppi_name_compare); + qsort(ppis, ppi_list_entries, sizeof(ppi), ppi_compare); i = ppi_list_entries - 1; ppi_list = NULL; @@ -1920,6 +2125,22 @@ } } +static void correct_abs_start_time(void) +{ + long delta = genesis_time - start_timestamp; + + abs_start_time.tv_sec += SECONDS(delta); + abs_start_time.tv_nsec += NANO_SECONDS(delta); + if (abs_start_time.tv_nsec < 0) { + abs_start_time.tv_nsec += 1000000000; + abs_start_time.tv_sec -= 1; + } else + if (abs_start_time.tv_nsec > 1000000000) { + abs_start_time.tv_nsec -= 1000000000; + abs_start_time.tv_sec += 1; + } +} + static void find_genesis(void) { struct trace *t = trace_list; @@ -1937,18 +2158,7 @@ */ if (start_timestamp && start_timestamp != genesis_time) { - long delta = genesis_time - start_timestamp; - - abs_start_time.tv_sec += SECONDS(delta); - abs_start_time.tv_nsec += NANO_SECONDS(delta); - if (abs_start_time.tv_nsec < 0) { - abs_start_time.tv_nsec += 1000000000; - abs_start_time.tv_sec -= 1; - } else - if (abs_start_time.tv_nsec > 1000000000) { - abs_start_time.tv_nsec -= 1000000000; - abs_start_time.tv_sec += 1; - } + correct_abs_start_time(); } } @@ -2127,7 +2337,7 @@ break; } - if (!(bit->action == BLK_TN_MESSAGE) && + if (!((bit->action & ~__BLK_TN_CGROUP) == BLK_TN_MESSAGE) && check_sequence(pdi, t, force)) break; @@ -2139,7 +2349,7 @@ if (!pci || pci->cpu != bit->cpu) pci = get_cpu_info(pdi, bit->cpu); - if (!(bit->action == BLK_TN_MESSAGE)) + if (!((bit->action & ~__BLK_TN_CGROUP) == BLK_TN_MESSAGE)) pci->last_sequence = bit->sequence; pci->nelems++; @@ -2273,7 +2483,7 @@ /* * not a real trace, so grab and handle it here */ - if (bit->action & BLK_TC_ACT(BLK_TC_NOTIFY) && bit->action != BLK_TN_MESSAGE) { + if (bit->action & BLK_TC_ACT(BLK_TC_NOTIFY) && (bit->action & ~__BLK_TN_CGROUP) != BLK_TN_MESSAGE) { handle_notify(bit); output_binary(bit, sizeof(*bit) + bit->pdu_len); continue; @@ -2422,7 +2632,7 @@ continue; } - if (bit->action & BLK_TC_ACT(BLK_TC_NOTIFY) && bit->action != BLK_TN_MESSAGE) { + if (bit->action & BLK_TC_ACT(BLK_TC_NOTIFY) && (bit->action & ~__BLK_TN_CGROUP) != BLK_TN_MESSAGE) { handle_notify(bit); output_binary(bit, sizeof(*bit) + bit->pdu_len); bit_free(bit); @@ -2603,6 +2813,14 @@ genesis_time = ms_peek_time(ms_head); /* + * Correct abs_start_time if necessary + */ + if (start_timestamp + && start_timestamp != genesis_time) { + correct_abs_start_time(); + } + + /* * Keep processing traces while any are left */ while (!is_done() && ms_head && handle(ms_head)) @@ -2671,6 +2889,7 @@ if (per_device_and_cpu_stats) show_device_and_cpu_stats(); + fprintf(ofp, "Trace started at %s\n", ctime(&abs_start_time.tv_sec)); fflush(ofp); } @@ -2730,7 +2949,46 @@ return 0; } -#define S_OPTS "a:A:b:D:d:f:F:hi:o:Oqstw:vVM" +static int get_program_sort_event(const char *str) +{ + char evt = str[0]; + + switch (evt) { + case 'N': + per_process_stats_event = SORT_PROG_EVENT_N; + break; + case 'Q': + per_process_stats_event = SORT_PROG_EVENT_QKB; + break; + case 'q': + per_process_stats_event = SORT_PROG_EVENT_QIO; + break; + case 'R': + per_process_stats_event = SORT_PROG_EVENT_RKB; + break; + case 'r': + per_process_stats_event = SORT_PROG_EVENT_RIO; + break; + case 'W': + per_process_stats_event = SORT_PROG_EVENT_WKB; + break; + case 'w': + per_process_stats_event = SORT_PROG_EVENT_WIO; + break; + case 'C': + per_process_stats_event = SORT_PROG_EVENT_CKB; + break; + case 'c': + per_process_stats_event = SORT_PROG_EVENT_CIO; + break; + default: + return 1; + } + + return 0; +} + +#define S_OPTS "a:A:b:D:d:f:F:hi:o:OqsS:tw:vVM" static char usage_str[] = "\n\n" \ "-i <file> | --input=<file>\n" \ "[ -a <action field> | --act-mask=<action field> ]\n" \ @@ -2745,6 +3003,7 @@ "[ -O | --no-text-output ]\n" \ "[ -q | --quiet ]\n" \ "[ -s | --per-program-stats ]\n" \ + "[ -S <event> | --sort-program-stats=<event> ]\n" \ "[ -t | --track-ios ]\n" \ "[ -w <time> | --stopwatch=<time> ]\n" \ "[ -M | --no-msgs\n" \ @@ -2764,6 +3023,11 @@ "\t-O Do NOT output text data\n" \ "\t-q Quiet. Don't display any stats at the end of the trace\n" \ "\t-s Show per-program io statistics\n" \ + "\t-S Show per-program io statistics sorted by N/Q/q/R/r/W/w/C/c\n" \ + "\t N:Name, Q/q:Queued(read & write), R/r:Queued Read, W/w:Queued Write, C/c:Complete.\n" \ + "\t Sort programs by how much data(KB): Q,R,W,C.\n" \ + "\t Sort programs by how many IO operations: q,r,w,c.\n" \ + "\t if -S was used, the -s parameter will be ignored.\n" \ "\t-t Track individual ios. Will tell you the time a request took\n" \ "\t to get queued, to get dispatched, and to get completed\n" \ "\t-w Only parse data between the given time interval in seconds.\n" \ @@ -2830,6 +3094,11 @@ case 's': per_process_stats = 1; break; + case 'S': + per_process_stats = 1; + if (get_program_sort_event(optarg)) + return 1; + break; case 't': track_ios = 1; break; diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn' '--exclude=.svnignore' old/blktrace-1.2.0+git.20180516/blkparse_fmt.c new/blktrace-1.3.0+git.20210628/blkparse_fmt.c --- old/blktrace-1.2.0+git.20180516/blkparse_fmt.c 2018-05-16 21:09:58.000000000 +0200 +++ new/blktrace-1.3.0+git.20210628/blkparse_fmt.c 2021-06-28 21:41:32.000000000 +0200 @@ -205,6 +205,21 @@ case 'e': fprintf(ofp, strcat(format, "d"), t->error); break; + case 'g': { + char cgidstr[24]; + u32 ino = 0, gen = 0; + + if (t->action & __BLK_TA_CGROUP) { + struct blk_io_cgroup_payload *cgid = + (struct blk_io_cgroup_payload *)pdu_buf; + + ino = cgid->ino; + gen = cgid->gen; + } + sprintf(cgidstr, "%x,%x", ino, gen); + fprintf(ofp, strcat(format, "s"), cgidstr); + break; + } case 'M': fprintf(ofp, strcat(format, "d"), MAJOR(t->device)); break; @@ -261,12 +276,12 @@ static char *parse_field(char *act, struct per_cpu_info *pci, struct blk_io_trace *t, unsigned long long elapsed, int pdu_len, unsigned char *pdu_buf, - char *master_format) + char *primary_format) { int minus = 0; int has_w = 0; int width = 0; - char *p = master_format; + char *p = primary_format; if (*p == '-') { minus = 1; diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn' '--exclude=.svnignore' old/blktrace-1.2.0+git.20180516/blktrace.c new/blktrace-1.3.0+git.20210628/blktrace.c --- old/blktrace-1.2.0+git.20180516/blktrace.c 2018-05-16 21:09:58.000000000 +0200 +++ new/blktrace-1.3.0+git.20210628/blktrace.c 2021-06-28 21:41:32.000000000 +0200 @@ -307,7 +307,7 @@ static volatile int dp_entries; /* - * These synchronize master / thread interactions. + * These synchronize main / thread interactions. */ static pthread_cond_t mt_cond = PTHREAD_COND_INITIALIZER; static pthread_mutex_t mt_mutex = PTHREAD_MUTEX_INITIALIZER; @@ -2705,8 +2705,10 @@ printf("blktrace: connected!\n"); if (stop_watch) alarm(stop_watch); - } else + } else { stop_tracers(); + done = 1; + } wait_tracers(); if (nthreads_running == ncpus) diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn' '--exclude=.svnignore' old/blktrace-1.2.0+git.20180516/blktrace_api.h new/blktrace-1.3.0+git.20210628/blktrace_api.h --- old/blktrace-1.2.0+git.20180516/blktrace_api.h 2018-05-16 21:09:58.000000000 +0200 +++ new/blktrace-1.3.0+git.20210628/blktrace_api.h 2021-06-28 21:41:32.000000000 +0200 @@ -51,6 +51,7 @@ __BLK_TA_REMAP, /* bio was remapped */ __BLK_TA_ABORT, /* request aborted */ __BLK_TA_DRV_DATA, /* binary driver data */ + __BLK_TA_CGROUP = 1 << 8, }; /* @@ -60,6 +61,7 @@ __BLK_TN_PROCESS = 0, /* establish pid/name mapping */ __BLK_TN_TIMESTAMP, /* include system clock */ __BLK_TN_MESSAGE, /* Character string message */ + __BLK_TN_CGROUP = __BLK_TA_CGROUP, }; /* @@ -117,6 +119,14 @@ }; /* + * Payload with originating cgroup info + */ +struct blk_io_cgroup_payload { + __u32 ino; + __u32 gen; +}; + +/* * User setup structure passed with BLKSTARTTRACE */ struct blk_user_trace_setup { diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn' '--exclude=.svnignore' old/blktrace-1.2.0+git.20180516/btreplay/btreplay.c new/blktrace-1.3.0+git.20210628/btreplay/btreplay.c --- old/blktrace-1.2.0+git.20180516/btreplay/btreplay.c 2018-05-16 21:09:58.000000000 +0200 +++ new/blktrace-1.3.0+git.20210628/btreplay/btreplay.c 2021-06-28 21:41:32.000000000 +0200 @@ -645,7 +645,7 @@ static void read_map_devs(char *file_name) { FILE *fp; - char from_dev[256], to_dev[256]; + char *from_dev, *to_dev; fp = fopen(file_name, "r"); if (!fp) { @@ -653,7 +653,7 @@ /*NOTREACHED*/ } - while (fscanf(fp, "%s %s", from_dev, to_dev) == 2) { + while (fscanf(fp, "%ms %ms", &from_dev, &to_dev) == 2) { struct map_dev *mdp = malloc(sizeof(*mdp)); mdp->from_dev = from_dev; diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn' '--exclude=.svnignore' old/blktrace-1.2.0+git.20180516/btt/bno_plot.py new/blktrace-1.3.0+git.20210628/btt/bno_plot.py --- old/blktrace-1.2.0+git.20180516/btt/bno_plot.py 2018-05-16 21:09:58.000000000 +0200 +++ new/blktrace-1.3.0+git.20210628/btt/bno_plot.py 2021-06-28 21:41:32.000000000 +0200 @@ -40,7 +40,7 @@ from __future__ import absolute_import from __future__ import print_function -import getopt, glob, os, sys, tempfile +import getopt, glob, os, sys, tempfile, shutil verbose = 0 cmds = """ @@ -76,7 +76,7 @@ elif o in ('-K', '--keys-below'): keys_below = True - if len(args) > 0: bnos = args + if args: bnos = args else: bnos = glob.glob('blknos*[rw].dat') return (bnos, keys_below) @@ -98,21 +98,20 @@ for f in bnos: t = '%s/%s' % (tmpdir, f) - fo = open(t, 'w') - for line in open(f, 'r'): - fld = line.split(None) - print(fld[0], fld[1], int(fld[2])-int(fld[1]), file=fo) - fo.close() + with open(t, 'w') as fo: + with open(f, 'r') as fi: + for line in fi: + fld = line.split(None) + print(fld[0], fld[1], int(fld[2])-int(fld[1]), file=fo) t = t[t.rfind('/')+1:] - if plot_cmd == None: plot_cmd = "splot '%s'" % t + if plot_cmd is None: plot_cmd = "splot '%s'" % t else: plot_cmd = "%s,'%s'" % (plot_cmd, t) - fo = open('%s/plot.cmds' % tmpdir, 'w') - print(cmds, file=fo) - if len(bnos) > 10 or keys_below: print('set key below', file=fo) - print(plot_cmd, file=fo) - fo.close() + with open('%s/plot.cmds' % tmpdir, 'w') as fo: + print(cmds, file=fo) + if len(bnos) > 10 or keys_below: print('set key below', file=fo) + print(plot_cmd, file=fo) pid = os.fork() if pid == 0: @@ -125,4 +124,4 @@ sys.exit(1) os.waitpid(pid, 0) - os.system('/bin/rm -rf ' + tmpdir) + shutil.rmtree(tmpdir) diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn' '--exclude=.svnignore' old/blktrace-1.2.0+git.20180516/btt/btt_plot.py new/blktrace-1.3.0+git.20210628/btt/btt_plot.py --- old/blktrace-1.2.0+git.20180516/btt/btt_plot.py 2018-05-16 21:09:58.000000000 +0200 +++ new/blktrace-1.3.0+git.20210628/btt/btt_plot.py 2021-06-28 21:41:32.000000000 +0200 @@ -57,6 +57,7 @@ from __future__ import absolute_import from __future__ import print_function +import getopt, glob, os, sys import six from six.moves import range __author__ = 'Alan D. Brunelle <alan.brune...@hp.com>' @@ -65,7 +66,6 @@ import matplotlib matplotlib.use('Agg') -import getopt, glob, os, sys import matplotlib.pyplot as plt plot_size = [10.9, 8.4] # inches... @@ -113,8 +113,8 @@ """Returns new min, max, and float value for those passed in""" v = float(v) - if mn == None or v < mn: mn = v - if mx == None or v > mx: mx = v + if mn is None or v < mn: mn = v + if mx is None or v > mx: mx = v return mn, mx, v #-------------------------------------------------------------- @@ -125,10 +125,7 @@ def _avg(vals): """Computes average for array of values passed""" - total = 0.0 - for val in vals: - total += val - return total / len(vals) + return sum(vals) / len(vals) #------------------------------------------------------ if len(xs) < 1000: @@ -171,14 +168,15 @@ xs = [] ys = [] - for line in open(file, 'r'): - f = line.rstrip().split(None) - if line.find('#') == 0 or len(f) < 2: - continue - (min_x, max_x, x) = check(min_x, max_x, f[0]) - (min_y, max_y, y) = check(min_y, max_y, f[1]) - xs.append(x) - ys.append(y) + with open(file, 'r') as fi: + for line in fi: + f = line.rstrip().split(None) + if line.find('#') == 0 or len(f) < 2: + continue + (min_x, max_x, x) = check(min_x, max_x, f[0]) + (min_y, max_y, y) = check(min_y, max_y, f[1]) + xs.append(x) + ys.append(y) db[file] = {'x':xs, 'y':ys} if len(xs) > 10: @@ -238,7 +236,7 @@ elif o in ('-v', '--verbose'): verbose = True - if type == None and not generate_all: + if type is None and not generate_all: fatal('Need type of data files to process - (-t <type>)') return args @@ -247,7 +245,7 @@ def gen_title(fig, type, title_str): """Sets the title for the figure based upon the type /or/ user title""" - if title_str != None: + if title_str is not None: pass elif type == 'aqd': title_str = 'Average Queue Depth' @@ -312,7 +310,7 @@ #---------------------------------------------------------------------- global add_legend, output_file, title_str, verbose - if output_file != None: + if output_file is not None: ofile = output_file else: ofile = '%s.png' % type @@ -343,7 +341,7 @@ if type == 'bnos': ax.plot(dat['x'], dat['y'], color(idx, 'marker'), markersize=1) - elif dat['ax'] == None: + elif dat['ax'] is None: continue # Don't add legend else: ax.plot(dat['ax'], dat['ay'], color(idx, 'line'), @@ -352,7 +350,7 @@ legends.append(get_base(file)) idx += 1 - if add_legend and len(legends) > 0: + if add_legend and legends: gen_legends(ax, legends) plt.savefig(ofile) @@ -388,23 +386,23 @@ def get_live_data(fn): xs = [] ys = [] - for line in open(fn, 'r'): - f = line.rstrip().split() - if f[0] != '#' and len(f) == 2: - xs.append(float(f[0])) - ys.append(float(f[1])) + with open(fn, 'r') as fi: + for line in fi: + f = line.rstrip().split() + if f[0] != '#' and len(f) == 2: + xs.append(float(f[0])) + ys.append(float(f[1])) return xs, ys #---------------------------------------------------------------------- def live_sort(a, b): if a[0] == 'sys' and b[0] == 'sys': return 0 - elif a[0] == 'sys' or a[2][0] < b[2][0]: + if a[0] == 'sys' or a[2][0] < b[2][0]: return -1 - elif b[0] == 'sys' or a[2][0] > b[2][0]: + if b[0] == 'sys' or a[2][0] > b[2][0]: return 1 - else: - return 0 + return 0 #---------------------------------------------------------------------- def turn_off_ticks(ax): @@ -453,7 +451,7 @@ output_file = title_str = type = None for t in types: files = get_files(t) - if len(files) == 0: + if files == 0: continue elif t == 'bnos': do_bnos(files) @@ -463,7 +461,7 @@ generate_output(t, get_data(files)) continue - elif len(files) < 1: + elif not files: fatal('Need data files to process') else: generate_output(type, get_data(files)) diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn' '--exclude=.svnignore' old/blktrace-1.2.0+git.20180516/doc/blkparse.1 new/blktrace-1.3.0+git.20210628/doc/blkparse.1 --- old/blktrace-1.2.0+git.20180516/doc/blkparse.1 2018-05-16 21:09:58.000000000 +0200 +++ new/blktrace-1.3.0+git.20210628/doc/blkparse.1 2021-06-28 21:41:32.000000000 +0200 @@ -165,6 +165,21 @@ Displays data sorted by program .RE +\-S \fIevent\fR +.br +\-\-sort\-program\-stats=\fIevent\fR +.br +.RS +Displays each program's data sorted by program name or io event, like +Queued, Read, Write and Complete. When \-S is specified the \-s will be ignored. +The capital letters Q,R,W,C stand for KB, then q/r/w/c stand for IO. + +If you want to soct programs by how many data they queued, you can use: + +blkparse -i sda.blktrace. -q \-S Q \-o sda.parse +.RE + + \-t .br \-\-track\-ios @@ -317,6 +332,10 @@ .IP \fBe\fR 4 Error value +.IP \fBg\fR 4 +Cgroup identifier of the cgroup that generated the IO. Note that this requires +appropriate kernel support (kernel version at least 4.14). + .IP \fBm\fR 4 Minor number of event's device. @@ -353,6 +372,9 @@ .IP \fBU\fR 4 Payload unsigned integer +.IP \fBz\fR 4 +The absolute time, as local time in your time zone, with no date displayed + .PP Note that the user can optionally specify field display width, and optionally a left-aligned specifier. These precede field specifiers, with a '%' character, diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn' '--exclude=.svnignore' old/blktrace-1.2.0+git.20180516/doc/blktrace.tex new/blktrace-1.3.0+git.20210628/doc/blktrace.tex --- old/blktrace-1.2.0+git.20180516/doc/blktrace.tex 2018-05-16 21:09:58.000000000 +0200 +++ new/blktrace-1.3.0+git.20210628/doc/blktrace.tex 2021-06-28 21:41:32.000000000 +0200 @@ -601,6 +601,9 @@ the event's device \\ & (separated by a comma). \\ \hline \emph{e} & Error value \\ \hline +\emph{g} & Cgroup identifier of the cgroup that generated the IO. Note that this requires +appropriate \\ + & kernel support (kernel version at least 4.14). \\ \hline \emph{m} & Minor number of event's device. \\ \hline \emph{M} & Major number of event's device. \\ \hline \emph{n} & Number of blocks \\ \hline @@ -613,6 +616,7 @@ \emph{T} & Time stamp (seconds) \\ \hline \emph{u} & Elapsed value in microseconds (\emph{-t} command line option) \\ \hline \emph{U} & Payload unsigned integer \\ \hline +\emph{z} & Absolute time stamp \\ \hline \end{tabular} Note that the user can optionally specify field display width, and diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn' '--exclude=.svnignore' old/blktrace-1.2.0+git.20180516/iowatcher/blkparse.c new/blktrace-1.3.0+git.20210628/iowatcher/blkparse.c --- old/blktrace-1.2.0+git.20180516/iowatcher/blkparse.c 2018-05-16 21:09:58.000000000 +0200 +++ new/blktrace-1.3.0+git.20210628/iowatcher/blkparse.c 2021-06-28 21:41:32.000000000 +0200 @@ -36,6 +36,7 @@ #include "blkparse.h" #include "list.h" #include "tracers.h" +#include "../blktrace_api.h" #define IO_HASH_TABLE_BITS 11 #define IO_HASH_TABLE_SIZE (1 << IO_HASH_TABLE_BITS) @@ -49,111 +50,8 @@ extern int plot_io_action; extern int io_per_process; -/* - * Trace categories - */ -enum { - BLK_TC_READ = 1 << 0, /* reads */ - BLK_TC_WRITE = 1 << 1, /* writes */ - BLK_TC_FLUSH = 1 << 2, /* flush */ - BLK_TC_SYNC = 1 << 3, /* sync */ - BLK_TC_QUEUE = 1 << 4, /* queueing/merging */ - BLK_TC_REQUEUE = 1 << 5, /* requeueing */ - BLK_TC_ISSUE = 1 << 6, /* issue */ - BLK_TC_COMPLETE = 1 << 7, /* completions */ - BLK_TC_FS = 1 << 8, /* fs requests */ - BLK_TC_PC = 1 << 9, /* pc requests */ - BLK_TC_NOTIFY = 1 << 10, /* special message */ - BLK_TC_AHEAD = 1 << 11, /* readahead */ - BLK_TC_META = 1 << 12, /* metadata */ - BLK_TC_DISCARD = 1 << 13, /* discard requests */ - BLK_TC_DRV_DATA = 1 << 14, /* binary driver data */ - BLK_TC_FUA = 1 << 15, /* fua requests */ - - BLK_TC_END = 1 << 15, /* we've run out of bits! */ -}; - -#define BLK_TC_SHIFT (16) -#define BLK_TC_ACT(act) ((act) << BLK_TC_SHIFT) #define BLK_DATADIR(a) (((a) >> BLK_TC_SHIFT) & (BLK_TC_READ | BLK_TC_WRITE)) - -/* - * Basic trace actions - */ -enum { - __BLK_TA_QUEUE = 1, /* queued */ - __BLK_TA_BACKMERGE, /* back merged to existing rq */ - __BLK_TA_FRONTMERGE, /* front merge to existing rq */ - __BLK_TA_GETRQ, /* allocated new request */ - __BLK_TA_SLEEPRQ, /* sleeping on rq allocation */ - __BLK_TA_REQUEUE, /* request requeued */ - __BLK_TA_ISSUE, /* sent to driver */ - __BLK_TA_COMPLETE, /* completed by driver */ - __BLK_TA_PLUG, /* queue was plugged */ - __BLK_TA_UNPLUG_IO, /* queue was unplugged by io */ - __BLK_TA_UNPLUG_TIMER, /* queue was unplugged by timer */ - __BLK_TA_INSERT, /* insert request */ - __BLK_TA_SPLIT, /* bio was split */ - __BLK_TA_BOUNCE, /* bio was bounced */ - __BLK_TA_REMAP, /* bio was remapped */ - __BLK_TA_ABORT, /* request aborted */ - __BLK_TA_DRV_DATA, /* binary driver data */ -}; - -#define BLK_TA_MASK ((1 << BLK_TC_SHIFT) - 1) - -/* - * Notify events. - */ -enum blktrace_notify { - __BLK_TN_PROCESS = 0, /* establish pid/name mapping */ - __BLK_TN_TIMESTAMP, /* include system clock */ - __BLK_TN_MESSAGE, /* Character string message */ -}; - -/* - * Trace actions in full. Additionally, read or write is masked - */ -#define BLK_TA_QUEUE (__BLK_TA_QUEUE | BLK_TC_ACT(BLK_TC_QUEUE)) -#define BLK_TA_BACKMERGE (__BLK_TA_BACKMERGE | BLK_TC_ACT(BLK_TC_QUEUE)) -#define BLK_TA_FRONTMERGE (__BLK_TA_FRONTMERGE | BLK_TC_ACT(BLK_TC_QUEUE)) -#define BLK_TA_GETRQ (__BLK_TA_GETRQ | BLK_TC_ACT(BLK_TC_QUEUE)) -#define BLK_TA_SLEEPRQ (__BLK_TA_SLEEPRQ | BLK_TC_ACT(BLK_TC_QUEUE)) -#define BLK_TA_REQUEUE (__BLK_TA_REQUEUE | BLK_TC_ACT(BLK_TC_REQUEUE)) -#define BLK_TA_ISSUE (__BLK_TA_ISSUE | BLK_TC_ACT(BLK_TC_ISSUE)) -#define BLK_TA_COMPLETE (__BLK_TA_COMPLETE| BLK_TC_ACT(BLK_TC_COMPLETE)) -#define BLK_TA_PLUG (__BLK_TA_PLUG | BLK_TC_ACT(BLK_TC_QUEUE)) -#define BLK_TA_UNPLUG_IO (__BLK_TA_UNPLUG_IO | BLK_TC_ACT(BLK_TC_QUEUE)) -#define BLK_TA_UNPLUG_TIMER (__BLK_TA_UNPLUG_TIMER | BLK_TC_ACT(BLK_TC_QUEUE)) -#define BLK_TA_INSERT (__BLK_TA_INSERT | BLK_TC_ACT(BLK_TC_QUEUE)) -#define BLK_TA_SPLIT (__BLK_TA_SPLIT) -#define BLK_TA_BOUNCE (__BLK_TA_BOUNCE) -#define BLK_TA_REMAP (__BLK_TA_REMAP | BLK_TC_ACT(BLK_TC_QUEUE)) -#define BLK_TA_ABORT (__BLK_TA_ABORT | BLK_TC_ACT(BLK_TC_QUEUE)) -#define BLK_TA_DRV_DATA (__BLK_TA_DRV_DATA | BLK_TC_ACT(BLK_TC_DRV_DATA)) - -#define BLK_TN_PROCESS (__BLK_TN_PROCESS | BLK_TC_ACT(BLK_TC_NOTIFY)) -#define BLK_TN_TIMESTAMP (__BLK_TN_TIMESTAMP | BLK_TC_ACT(BLK_TC_NOTIFY)) -#define BLK_TN_MESSAGE (__BLK_TN_MESSAGE | BLK_TC_ACT(BLK_TC_NOTIFY)) - -#define BLK_IO_TRACE_MAGIC 0x65617400 -#define BLK_IO_TRACE_VERSION 0x07 -/* - * The trace itself - */ -struct blk_io_trace { - __u32 magic; /* MAGIC << 8 | version */ - __u32 sequence; /* event number */ - __u64 time; /* in nanoseconds */ - __u64 sector; /* disk offset */ - __u32 bytes; /* transfer length */ - __u32 action; /* what happened */ - __u32 pid; /* who did it */ - __u32 device; /* device identifier (dev_t) */ - __u32 cpu; /* on what cpu did it happen */ - __u16 error; /* completion error */ - __u16 pdu_len; /* length of data after this trace */ -}; +#define BLK_TA_MASK (((1 << BLK_TC_SHIFT) - 1) & ~__BLK_TA_CGROUP) struct pending_io { /* sector offset of this IO */ @@ -362,18 +260,23 @@ { struct blk_io_trace *io = trace->io; void *payload = (char *)io + sizeof(*io); + int pdu_len = io->pdu_len; u32 two32[2]; - if (io->action == BLK_TN_PROCESS) { + if (io->action & __BLK_TN_CGROUP) { + payload += sizeof(struct blk_io_cgroup_payload); + pdu_len -= sizeof(struct blk_io_cgroup_payload); + } + if ((io->action & ~__BLK_TN_CGROUP) == BLK_TN_PROCESS) { if (io_per_process) process_hash_insert(io->pid, payload); return; } - if (io->action != BLK_TN_TIMESTAMP) + if ((io->action & ~__BLK_TN_CGROUP) != BLK_TN_TIMESTAMP) return; - if (io->pdu_len != sizeof(two32)) + if (pdu_len != sizeof(two32)) return; memcpy(two32, payload, sizeof(two32)); @@ -411,11 +314,16 @@ char *message; if (!(test->action & BLK_TC_ACT(BLK_TC_NOTIFY))) return 1; - if (test->action == BLK_TN_MESSAGE) { + if ((test->action & ~__BLK_TN_CGROUP) == BLK_TN_MESSAGE) { int len = test->pdu_len; + + message = (char *)(test + 1); + if (test->action & __BLK_TN_CGROUP) { + len -= sizeof(struct blk_io_cgroup_payload); + message += sizeof(struct blk_io_cgroup_payload); + } if (len < 3) return 0; - message = (char *)(test + 1); if (strncmp(message, "fio ", 4) == 0) { return 1; } @@ -474,13 +382,17 @@ if (!(test->action & BLK_TC_ACT(BLK_TC_NOTIFY))) return -1; - if (test->action != BLK_TN_MESSAGE) + if ((test->action & ~__BLK_TN_CGROUP) != BLK_TN_MESSAGE) return -1; + message = (char *)(test + 1); + if (test->action & __BLK_TN_CGROUP) { + len -= sizeof(struct blk_io_cgroup_payload); + message += sizeof(struct blk_io_cgroup_payload); + } /* the message is fio rw bank offset num_banks */ if (len < 3) return -1; - message = (char *)(test + 1); if (strncmp(message, "fio r ", 6) != 0) return -1; @@ -1099,16 +1011,28 @@ if (action == __BLK_TA_QUEUE) { if (io->sector == 0) return; - if (trace->found_issue || trace->found_completion) { - pio = hash_queued_io(trace->io); - /* - * When there are no ISSUE events count depth and - * latency at least from queue events - */ - if (pio && !trace->found_issue) { - pio->dispatch_time = io->time; - goto account_io; - } + /* + * If D (issue) events are available, use them for I/O + * accounting. Nothing needs to be done for Q. + */ + if (trace->found_issue) + return; + /* + * If there are no D or C events, then all that can be + * done is to account the Q event (and make sure not to + * add the I/O to the hash, because it will never be + * removed). + */ + if (!trace->found_completion) + goto account_io; + /* + * When there are no ISSUE events, count depth and + * latency from queue events. + */ + pio = hash_queued_io(trace->io); + if (pio) { + pio->dispatch_time = io->time; + goto account_io; } return; } diff -urN '--exclude=CVS' '--exclude=.cvsignore' '--exclude=.svn' '--exclude=.svnignore' old/blktrace-1.2.0+git.20180516/iowatcher/main.c new/blktrace-1.3.0+git.20210628/iowatcher/main.c --- old/blktrace-1.2.0+git.20180516/iowatcher/main.c 2018-05-16 21:09:58.000000000 +0200 +++ new/blktrace-1.3.0+git.20210628/iowatcher/main.c 2021-06-28 21:41:32.000000000 +0200 @@ -1043,9 +1043,14 @@ static void convert_movie_files(char *movie_dir) { + long nr_cpus = sysconf(_SC_NPROCESSORS_ONLN); + + if (nr_cpus < 0) + nr_cpus = 8; + fprintf(stderr, "Converting svg files in %s\n", movie_dir); - snprintf(line, line_len, "find %s -name \\*.svg | xargs -I{} -n 1 -P 8 rsvg-convert -o {}.png {}", - movie_dir); + snprintf(line, line_len, "find %s -name \\*.svg | xargs -I{} -n 1 -P %ld rsvg-convert -o {}.png {}", + movie_dir, nr_cpus); system_check(line); }
