Hi Rezki, Thank you so much for sharing this super cool parser! ;-) It will help me/us to speed up parsing the tracing logs. -Qiuxu > From: Uladzislau Rezki <urezki@xxxxxxxxx> > Sent: Wednesday, March 22, 2023 2:50 PM > To: Zhuo, Qiuxu <qiuxu.zhuo@xxxxxxxxx> > Cc: Uladzislau Rezki <urezki@xxxxxxxxx>; Paul E . McKenney > <paulmck@xxxxxxxxxx>; RCU <rcu@xxxxxxxxxxxxxxx>; > quic_neeraju@xxxxxxxxxxx; Boqun Feng <boqun.feng@xxxxxxxxx>; Joel > Fernandes <joel@xxxxxxxxxxxxxxxxx>; LKML <linux-kernel@xxxxxxxxxxxxxxx>; > Oleksiy Avramchenko <oleksiy.avramchenko@xxxxxxxx>; Steven Rostedt > <rostedt@xxxxxxxxxxx>; Frederic Weisbecker <frederic@xxxxxxxxxx> > Subject: Re: [PATCH 1/1] Reduce synchronize_rcu() waiting time > > On Wed, Mar 22, 2023 at 01:49:50AM +0000, Zhuo, Qiuxu wrote: > > Hi Rezki, > > > > > From: Uladzislau Rezki <urezki@xxxxxxxxx> > > > Sent: Tuesday, March 21, 2023 11:16 PM [...] > > > > > > > > > > > > If possible, may I know the steps, commands, and related > > > > parameters to > > > produce the results above? > > > > Thank you! > > > > > > > Build the kernel with CONFIG_RCU_TRACE configuration. Update your > > > "set_event" > > > file with appropriate traces: > > > > > > <snip> > > > XQ-DQ54:/sys/kernel/tracing # echo rcu:rcu_batch_start > > > rcu:rcu_batch_end rcu:rcu_invoke_callback > set_event > > > > > > XQ-DQ54:/sys/kernel/tracing # cat set_event rcu:rcu_batch_start > > > rcu:rcu_invoke_callback rcu:rcu_batch_end > > > XQ-DQ54:/sys/kernel/tracing # <snip> > > > > > > Collect traces as much as you want: XQ-DQ54:/sys/kernel/tracing # > > > echo 1 > tracing_on; sleep 10; echo 0 > tracing_on Next problem is > > > how to parse it. Of > > > > Thanks for the detailed steps to collect the related testing results. > > > > > course you will not be able to parse megabytes of traces. For that > > > purpose i use a special C trace parser. > > > If you need an example please let me know i can show here. > > > > > > > Yes, your example parser should save me from a huge amount of traces. > > ;-) Thanks so much for your sharing. > > > See below the C program. It is ugly but it does what you need. Please have a > look at main function: > > <snip> > #include <stdio.h> > #include <stdlib.h> > #include <stdbool.h> > #include <ctype.h> > #include <string.h> > > /* > * Splay-tree implementation to store data: key,value > * See https://en.wikipedia.org/wiki/Splay_tree > */ > #define offsetof(TYPE, MEMBER) ((unsigned long)&((TYPE *)0)- > >MEMBER) > #define container_of(ptr, type, member) \ > ({ > \ > void *__mptr = (void *)(ptr); \ > ((type *)(__mptr - offsetof(type, member))); \ > }) > > #define SP_INIT_NODE(node) > \ > ((node)->left = (node)->right = (node)->parent = NULL) > > struct splay_node { > struct splay_node *left; > struct splay_node *right; > struct splay_node *parent; > unsigned long val; > }; > > struct splay_root { > struct splay_node *sp_root; > }; > > static inline void > set_parent(struct splay_node *n, struct splay_node *p) { > if (n) > n->parent = p; > } > > static inline void > change_child(struct splay_node *p, > struct splay_node *old, struct splay_node *new) { > if (p) { > if (p->left == old) > p->left = new; > else > p->right = new; > } > } > > /* > * left rotation of node (r), (rc) is (r)'s right child */ static inline struct > splay_node * left_pivot(struct splay_node *r) { > struct splay_node *rc; > > /* > * set (rc) to be the new root > */ > rc = r->right; > > /* > * point parent to new left/right child > */ > rc->parent = r->parent; > > /* > * change child of the p->parent. > */ > change_child(r->parent, r, rc); > > /* > * set (r)'s right child to be (rc)'s left child > */ > r->right = rc->left; > > /* > * change parent of rc's left child > */ > set_parent(rc->left, r); > > /* > * set new parent of rotated node > */ > r->parent = rc; > > /* > * set (rc)'s left child to be (r) > */ > rc->left = r; > > /* > * return the new root > */ > return rc; > } > > /* > * right rotation of node (r), (lc) is (r)'s left child */ static inline struct > splay_node * right_pivot(struct splay_node *r) { > struct splay_node *lc; > > /* > * set (lc) to be the new root > */ > lc = r->left; > > /* > * point parent to new left/right child > */ > lc->parent = r->parent; > > /* > * change child of the p->parent. > */ > change_child(r->parent, r, lc); > > /* > * set (r)'s left child to be (lc)'s right child > */ > r->left = lc->right; > > /* > * change parent of lc's right child > */ > set_parent(lc->right, r); > > /* > * set new parent of rotated node > */ > r->parent = lc; > > /* > * set (lc)'s right child to be (r) > */ > lc->right = r; > > /* > * return the new root > */ > return lc; > } > > static struct splay_node * > top_down_splay(unsigned long vstart, > struct splay_node *root, struct splay_root *sp_root) { > /* > * During the splitting process two temporary trees are formed. > * "l" contains all keys less than the search key/vstart and "r" > * contains all keys greater than the search key/vstart. > */ > struct splay_node head, *ltree_max, *rtree_max; > struct splay_node *ltree_prev, *rtree_prev; > > if (root == NULL) > return NULL; > > SP_INIT_NODE(&head); > ltree_max = rtree_max = &head; > ltree_prev = rtree_prev = NULL; > > while (1) { > if (vstart < root->val && root->left) { > if (vstart < root->left->val) { > root = right_pivot(root); > > if (root->left == NULL) > break; > } > > /* > * Build right subtree. > */ > rtree_max->left = root; > rtree_max->left->parent = rtree_prev; > rtree_max = rtree_max->left; > rtree_prev = root; > root = root->left; > } else if (vstart > root->val && root->right) { > if (vstart > root->right->val) { > root = left_pivot(root); > > if (root->right == NULL) > break; > } > > /* > * Build left subtree. > */ > ltree_max->right = root; > ltree_max->right->parent = ltree_prev; > ltree_max = ltree_max->right; > ltree_prev = root; > root = root->right; > } else { > break; > } > } > > /* > * Assemble the tree. > */ > ltree_max->right = root->left; > rtree_max->left = root->right; > root->left = head.right; > root->right = head.left; > > set_parent(ltree_max->right, ltree_max); > set_parent(rtree_max->left, rtree_max); > set_parent(root->left, root); > set_parent(root->right, root); > root->parent = NULL; > > /* > * Set new root. Please note it might be the same. > */ > sp_root->sp_root = root; > return sp_root->sp_root; > } > > struct splay_node * > splay_search(unsigned long key, struct splay_root *root) { > struct splay_node *n; > > n = top_down_splay(key, root->sp_root, root); > if (n && n->val == key) > return n; > > return NULL; > } > > static bool > splay_insert(struct splay_node *n, struct splay_root *sp_root) { > struct splay_node *r; > > SP_INIT_NODE(n); > > r = top_down_splay(n->val, sp_root->sp_root, sp_root); > if (r == NULL) { > /* First element in the tree */ > sp_root->sp_root = n; > return false; > } > > if (n->val < r->val) { > n->left = r->left; > n->right = r; > > set_parent(r->left, n); > r->parent = n; > r->left = NULL; > } else if (n->val > r->val) { > n->right = r->right; > n->left = r; > > set_parent(r->right, n); > r->parent = n; > r->right = NULL; > } else { > /* > * Same, indicate as not success insertion. > */ > return false; > } > > sp_root->sp_root = n; > return true; > } > > static bool > splay_delete_init(struct splay_node *n, struct splay_root *sp_root) { > struct splay_node *subtree[2]; > unsigned long val = n->val; > > /* 1. Splay the node to the root. */ > n = top_down_splay(n->val, sp_root->sp_root, sp_root); > if (n == NULL || n->val != val) > return false; > > /* 2. Save left/right sub-trees. */ > subtree[0] = n->left; > subtree[1] = n->right; > > /* 3. Now remove the node. */ > SP_INIT_NODE(n); > > if (subtree[0]) { > /* 4. Splay the largest node in left sub-tree to the root. */ > top_down_splay(val, subtree[0], sp_root); > > /* 5. Attach the right sub-tree as the right child of the left > sub-tree. */ > sp_root->sp_root->right = subtree[1]; > > /* 6. Update the parent of right sub-tree */ > set_parent(subtree[1], sp_root->sp_root); > } else { > /* 7. Left sub-tree is NULL, just point to right one. */ > sp_root->sp_root = subtree[1]; > } > > /* 8. Set parent of root node to NULL. */ > if (sp_root->sp_root) > sp_root->sp_root->parent = NULL; > > return true; > } > > static FILE * > open_perf_script_file(const char *path) > { > FILE *f = NULL; > > if (path == NULL) > goto out; > > f = fopen(path, "r"); > if (!f) > goto out; > > out: > return f; > } > > static int > get_one_line(FILE *file, char *buf, size_t len) { > int i = 0; > > memset(buf, '\0', len); > > for (i = 0; i < len - 1; i++) { > int c = fgetc(file); > > if (c == EOF) > return EOF; > > if (c == '\n') > break; > > if (c != '\r') > buf[i] = c; > } > > return i; > } > > static int > read_string_till_string(char *buf, char *out, size_t out_len, char *in, size_t > in_len) { > int i, j; > > memset(out, '\0', out_len); > > for (i = 0; i < out_len; i++) { > if (buf[i] != in[0]) { > out[i] = buf[i]; > continue; > } > > for (j = 0; j < in_len; j++) { > if (buf[i + j] != in[j]) > break; > } > > /* Found. */ > if (j == in_len) > return 1; > } > > return 0; > } > > /* > * find pattern is "something [003] 8640.034785: something" > */ > static inline void > get_cpu_sec_usec_in_string(const char *s, int *cpu, int *sec, int *usec) { > char usec_buf[32] = {'\0'}; > char sec_buf[32] = {'\0'}; > char cpu_buf[32] = {'\0'}; > bool found_sec = false; > bool found_usec = false; > bool found_cpu = false; > int i, j, dot; > > *cpu = *sec = *usec = -1; > > for (i = 0, j = 0; s[i] != '\0'; i++) { > if (s[i] == '.') { > dot = i++; > > /* take microseconds */ > for (j = 0; j < sizeof(usec_buf); j++) { > if (isdigit(s[i])) { > usec_buf[j] = s[i]; > } else { > if (s[i] == ':' && j > 0) > found_usec = true; > else > found_usec = false; > > /* Terminate here. */ > break; > } > > i++; > } > > if (found_usec) { > /* roll back */ > while (s[i] != ' ' && i > 0) > i--; > > /* take seconds */ > for (j = 0; j < sizeof(sec_buf); j++) { > if (isdigit(s[++i])) { > sec_buf[j] = s[i]; > } else { > if (s[i] == '.' && j > 0) > found_sec = true; > else > found_sec = false; > > /* Terminate here. */ > break; > } > } > } > > if (found_sec && found_usec) { > /* roll back */ > while (s[i] != '[' && i > 0) > i--; > > /* take seconds */ > for (j = 0; j < sizeof(cpu_buf); j++) { > if (isdigit(s[++i])) { > cpu_buf[j] = s[i]; > } else { > if (s[i] == ']' && j > 0) > found_cpu = true; > else > found_cpu = false; > > /* Terminate here. */ > break; > } > } > > if (found_cpu && found_sec && found_usec) > { > *sec = atoi(sec_buf); > *usec = atoi(usec_buf); > *cpu = atoi(cpu_buf); > return; > } > } > > /* > * Check next dot pattern. > */ > found_sec = false; > found_usec = false; > found_cpu = false; > i = dot; > } > } > } > > /* > * find pattern is "something comm=foo android thr1 pid=123 something" > */ > static inline int > get_comm_pid_in_string(const char *buf, char *comm, ssize_t len, int *pid) { > char *sc, *sp; > int rv, i; > > memset(comm, '\0', len); > > sc = strstr(buf, "comm="); > if (sc) > sp = strstr(sc, " pid="); > > if (!sc || !sp) > return -1; > > for (i = 0, sc += 5; sc != sp; i++) { > if (i < len) { > if (*sc == ' ') > comm[i] = '-'; > else > comm[i] = *sc; > > sc++; > } > } > > /* Read pid. */ > rv = sscanf(sp, " pid=%d", pid); > if (rv != 1) > return -1; > > return 1; > } > > static void > perf_script_softirq_delay(FILE *file, int delay_usec) { > char buf[4096] = { '\0' }; > char buf_1[4096] = { '\0' }; > long offset; > char *s; > int rv; > > while (1) { > rv = get_one_line(file, buf, sizeof(buf)); > offset = ftell(file); > > if (rv != EOF) { > s = strstr(buf, "irq:softirq_raise:"); > if (s) { > char extra[512] = {'\0'}; > int sec_0, usec_0; > int sec_1, usec_1; > int handle_vector; > int rise_vector; > int cpu_0; > int cpu_1; > > /* > * swapper 0 [000] 6010.619854: > irq:softirq_raise: vec=7 [action=SCHED] > * android.bg 3052 [001] 6000.076212: > irq:softirq_entry: vec=9 [action=RCU] > */ > (void) sscanf(s, "%s vec=%d", extra, > &rise_vector); > get_cpu_sec_usec_in_string(buf, &cpu_0, > &sec_0, &usec_0); > > while (1) { > rv = get_one_line(file, buf_1, > sizeof(buf_1)); > if (rv == EOF) > break; > > s = strstr(buf_1, "irq:softirq_entry:"); > if (s) { > (void) sscanf(s, "%s vec=%d", > extra, &handle_vector); > > get_cpu_sec_usec_in_string(buf_1, &cpu_1, &sec_1, &usec_1); > > if (cpu_0 == cpu_1 && > rise_vector == handle_vector) { > int delta_time_usec = > (sec_1 - sec_0) * 1000000 + (usec_1 - usec_0); > > if (delta_time_usec > > delay_usec) > fprintf(stdout, > "{\n%s\n%s\n} diff %d usec\n", buf, buf_1, delta_time_usec); > break; > } > } > } > } > > rv = fseek(file, offset, SEEK_SET); > if (rv) > fprintf(stdout, "fseek error !!!\n"); > } else { > break; > } > } > } > > static void > perf_script_softirq_duration(FILE *file, int duration_usec) { > char buf[4096] = { '\0' }; > char buf_1[4096] = { '\0' }; > long offset; > char *s; > int rv; > > while (1) { > rv = get_one_line(file, buf, sizeof(buf)); > offset = ftell(file); > > if (rv != EOF) { > s = strstr(buf, "irq:softirq_entry:"); > if (s) { > char extra[512] = {'\0'}; > int sec_0, usec_0; > int sec_1, usec_1; > int handle_vector; > int rise_vector; > int cpu_0; > int cpu_1; > > /* > * swapper 0 [000] 6010.619854: > irq:softirq_entry: vec=7 [action=SCHED] > * android.bg 3052 [001] 6000.076212: > irq:softirq_exit: vec=9 [action=RCU] > */ > (void) sscanf(s, "%s vec=%d", extra, > &rise_vector); > get_cpu_sec_usec_in_string(buf, &cpu_0, > &sec_0, &usec_0); > > while (1) { > rv = get_one_line(file, buf_1, > sizeof(buf_1)); > if (rv == EOF) > break; > > s = strstr(buf_1, "irq:softirq_exit:"); > if (s) { > (void) sscanf(s, "%s vec=%d", > extra, &handle_vector); > > get_cpu_sec_usec_in_string(buf_1, &cpu_1, &sec_1, &usec_1); > > if (cpu_0 == cpu_1 && > rise_vector == handle_vector) { > int delta_time_usec = > (sec_1 - sec_0) * 1000000 + (usec_1 - usec_0); > > if (delta_time_usec > > duration_usec) > fprintf(stdout, > "{\n%s\n%s\n} diff %d usec\n", buf, buf_1, delta_time_usec); > break; > } > } > } > } > > rv = fseek(file, offset, SEEK_SET); > if (rv) > fprintf(stdout, "fseek error !!!\n"); > } else { > break; > } > } > } > > static void > perf_script_hardirq_duration(FILE *file, int duration_msec) { > char buf[4096] = { '\0' }; > char buf_1[4096] = { '\0' }; > long offset; > char *s; > int rv; > > while (1) { > rv = get_one_line(file, buf, sizeof(buf)); > offset = ftell(file); > > if (rv != EOF) { > s = strstr(buf, "irq:irq_handler_entry:"); > if (s) { > char extra[512] = {'\0'}; > int sec_0, usec_0; > int sec_1, usec_1; > int handle_vector; > int rise_vector; > int cpu_0; > int cpu_1; > > /* > * swapper 0 [002] 6205.804133: > irq:irq_handler_entry: irq=11 name=arch_timer > * swapper 0 [002] 6205.804228: > irq:irq_handler_exit: irq=11 ret=handled > */ > (void) sscanf(s, "%s irq=%d", extra, > &rise_vector); > get_cpu_sec_usec_in_string(buf, &cpu_0, > &sec_0, &usec_0); > > while (1) { > rv = get_one_line(file, buf_1, > sizeof(buf_1)); > if (rv == EOF) > break; > > s = strstr(buf_1, > "irq:irq_handler_exit:"); > if (s) { > (void) sscanf(s, "%s irq=%d", > extra, &handle_vector); > > get_cpu_sec_usec_in_string(buf_1, &cpu_1, &sec_1, &usec_1); > > if (cpu_0 == cpu_1 && > rise_vector == handle_vector) { > int delta_time_usec = > (sec_1 - sec_0) * 1000000 + (usec_1 - usec_0); > > if (delta_time_usec > > duration_msec) > fprintf(stdout, > "{\n%s\n%s\n} diff %d usec\n", buf, buf_1, delta_time_usec); > break; > } > } > } > } > > rv = fseek(file, offset, SEEK_SET); > if (rv) > fprintf(stdout, "fseek error !!!\n"); > } else { > break; > } > } > } > > struct irq_stat { > int irq; > int count; > char irq_name[512]; > > int min_interval; > int max_interval; > int avg_interval; > > unsigned int time_stamp_usec; > struct splay_node node; > }; > > static struct irq_stat * > new_irq_node_init(int irq, char *irq_name) { > struct irq_stat *n = calloc(1, sizeof(*n)); > > if (n) { > n->irq = irq; > (void) strncpy(n->irq_name, irq_name, sizeof(n->irq_name)); > n->node.val = irq; > } > > return n; > } > > static void > perf_script_hardirq_stat(FILE *file) > { > struct splay_root sproot = { NULL }; > struct irq_stat *node; > char buf[4096] = { '\0' }; > char extra[256] = {'\0'}; > char irq_name[256] = {'\0'}; > unsigned int time_stamp_usec; > int cpu, sec, usec; > int rv, irq; > char *s; > > while (1) { > rv = get_one_line(file, buf, sizeof(buf)); > if (rv == EOF) > break; > > s = strstr(buf, "irq:irq_handler_entry:"); > if (s == NULL) > continue; > > /* > * format is as follow one: > * sleep 1418 [003] 8780.957112: > irq:irq_handler_entry: irq=11 name=arch_timer > */ > rv = sscanf(s, "%s irq=%d name=%s", extra, &irq, irq_name); > if (rv != 3) > continue; > > get_cpu_sec_usec_in_string(buf, &cpu, &sec, &usec); > time_stamp_usec = (sec * 1000000) + usec; > > if (sproot.sp_root == NULL) { > node = new_irq_node_init(irq, irq_name); > if (node) > splay_insert(&node->node, &sproot); > } > > top_down_splay(irq, sproot.sp_root, &sproot); > node = container_of(sproot.sp_root, struct irq_stat, node); > > /* Found the entry in the tree. */ > if (node->irq == irq) { > if (node->time_stamp_usec) { > unsigned int delta = time_stamp_usec - > node->time_stamp_usec; > > if (delta < node->min_interval || !node- > >min_interval) > node->min_interval = delta; > > if (delta > node->max_interval) > node->max_interval = delta; > > node->avg_interval += delta; > } > > /* Save the last time for this IRQ entry. */ > node->time_stamp_usec = time_stamp_usec; > } else { > /* Allocate a new record and place it to the tree. */ > node = new_irq_node_init(irq, irq_name); > if (node) > splay_insert(&node->node, &sproot); > > } > > /* Update the timestamp for this entry. */ > node->time_stamp_usec = time_stamp_usec; > node->count++; > } > > /* Dump the tree. */ > while (sproot.sp_root) { > node = container_of(sproot.sp_root, struct irq_stat, node); > > fprintf(stdout, "irq: %5d name: %30s count: %7d, min: %10d, > max: %10d, avg: %10d\n", > node->irq, node->irq_name, node->count, > node->min_interval, node->max_interval, > node->avg_interval / node->count); > > splay_delete_init(&node->node, &sproot); > free(node); > } > > fprintf(stdout, "\tRun './a.out ./perf.script | sort -nk 6' to sort by > column 6.\n"); } > > struct sched_waking { > unsigned int wakeup_nr; > char comm[4096]; > int pid; > > int min; > int max; > int avg; > > unsigned int time_stamp_usec; > struct splay_node node; > }; > > static struct sched_waking * > new_sched_waking_node_init(int pid, char *comm) { > struct sched_waking *n = calloc(1, sizeof(*n)); > > if (n) { > n->pid = pid; > (void) strncpy(n->comm, comm, sizeof(n->comm)); > n->node.val = pid; > } > > return n; > } > > /* > * How many times a task is awaken + min/max/avg stat. > */ > static void > perf_script_sched_waking_stat(const char *name, FILE *file, const char > *script) { > struct splay_root sroot = { NULL }; > struct sched_waking *n; > char buf[4096] = { '\0' }; > char comm[256] = {'\0'}; > unsigned int time_stamp_usec; > unsigned int total_waking = 0; > int cpu, sec, usec; > int rv, pid; > char *s; > > while (1) { > rv = get_one_line(file, buf, sizeof(buf)); > if (rv == EOF) > break; > /* > * format is as follow one: > * foo[1] 7521 [002] 10.431216: sched_waking: comm=tr > pid=2 prio=120 target_cpu=006 > */ > s = strstr(buf, "sched_waking:"); > if (s == NULL) > continue; > > rv = get_comm_pid_in_string(s, comm, sizeof(comm), &pid); > if (rv < 0) { > printf("ERROR: skip entry...\n"); > continue; > } > > get_cpu_sec_usec_in_string(buf, &cpu, &sec, &usec); > time_stamp_usec = (sec * 1000000) + usec; > > if (sroot.sp_root == NULL) { > n = new_sched_waking_node_init(pid, comm); > if (n) > splay_insert(&n->node, &sroot); > } > > top_down_splay(pid, sroot.sp_root, &sroot); > n = container_of(sroot.sp_root, struct sched_waking, node); > > /* Found the entry in the tree. */ > if (n->pid == pid) { > if (n->time_stamp_usec) { > unsigned int delta = time_stamp_usec - n- > >time_stamp_usec; > > if (delta < n->min || !n->min) > n->min = delta; > > if (delta > n->max) > n->max = delta; > > n->avg += delta; > } > > /* Save the last time for this wake-up entry. */ > n->time_stamp_usec = time_stamp_usec; > } else { > /* Allocate a new record and place it to the tree. */ > n = new_sched_waking_node_init(pid, comm); > if (n) > splay_insert(&n->node, &sroot); > } > > /* Update the timestamp for this entry. */ > n->time_stamp_usec = time_stamp_usec; > n->wakeup_nr++; > } > > /* Dump the Splay-tree. */ > while (sroot.sp_root) { > n = container_of(sroot.sp_root, struct sched_waking, node); > fprintf(stdout, "name: %30s pid: %10d woken- > up %5d\tinterval: min %5d\tmax %5d\tavg %5d\n", > n->comm, n->pid, n->wakeup_nr, > n->min, n->max, n->avg / n->wakeup_nr); > > total_waking += n->wakeup_nr; > splay_delete_init(&n->node, &sroot); > free(n); > } > > fprintf(stdout, "=== Total: %u ===\n", total_waking); > fprintf(stdout, "\tRun './%s %s | sort -nk 6' to sort by column 6.\n", > name, script); } > > /* > * Latency of try_to_wake_up path + select a CPU + placing a task into run- > queue. > */ > static void > perf_script_sched_wakeup_latency(const char *name, FILE *file, const char > *script) { > struct splay_root sroot = { NULL }; > struct splay_node *node; > struct sched_waking *n; > char buf[4096] = { '\0' }; > char comm[256] = {'\0'}; > unsigned int time_stamp_usec; > unsigned int wakeup_latency_usec; > unsigned int total_waking = 0; > int cpu, sec, usec; > int rv, pid; > char *sched_waking_wakeup; > bool sched_waking_event; > > while (1) { > rv = get_one_line(file, buf, sizeof(buf)); > if (rv == EOF) > break; > > /* > * format is as follow one: > * foo[1] 7521 [002] 10.431216: sched_waking: comm=tr > pid=2 prio=120 target_cpu=006 > */ > sched_waking_wakeup = strstr(buf, "sched_waking:"); > sched_waking_event = !!sched_waking_wakeup; > > if (!sched_waking_event) { > /* > * format is as follow one: > * foo[1] 7521 [002] 10.431216: sched_wakeup: > comm=tr pid=2 prio=120 target_cpu=006 > */ > sched_waking_wakeup = strstr(buf, > "sched_wakeup:"); > if (sched_waking_wakeup == NULL) > continue; > } > > rv = get_comm_pid_in_string(sched_waking_wakeup, comm, > sizeof(comm), &pid); > if (rv < 0) { > printf("ERROR: skip entry...\n"); > continue; > } > > get_cpu_sec_usec_in_string(buf, &cpu, &sec, &usec); > time_stamp_usec = (sec * 1000000) + usec; > > /* > * Let's check if it exists, if so update it > * otherwise create a new node and insert. > */ > if (sched_waking_event) { > node = top_down_splay(pid, sroot.sp_root, &sroot); > if (node == NULL) { > n = new_sched_waking_node_init(pid, > comm); > splay_insert(&n->node, &sroot); > } else { > n = container_of(node, struct sched_waking, > node); > if (n->pid != pid) { > n = new_sched_waking_node_init(pid, > comm); > splay_insert(&n->node, &sroot); > } > } > > n->time_stamp_usec = time_stamp_usec; > continue; > } > > node = top_down_splay(pid, sroot.sp_root, &sroot); > if (node == NULL) { > fprintf(stdout, "error: no sched_waking event for %d > pid yet.\n", pid); > continue; > } > > n = container_of(node, struct sched_waking, node); > if (n->pid != pid) { > fprintf(stdout, "error: sched_wakeup event does not > match with any sched_waking event.\n"); > continue; > } > > wakeup_latency_usec = time_stamp_usec - n- > >time_stamp_usec; > > if (wakeup_latency_usec < n->min || !n->min) > n->min = wakeup_latency_usec; > > if (wakeup_latency_usec > n->max) > n->max = wakeup_latency_usec; > > if (n->avg + wakeup_latency_usec < n->avg) > fprintf(stdout, "error: counter is overflowed...\n"); > > fprintf(stdout, "%s: %d wake-up latency: %u waken on %d > CPU\n", comm, pid, wakeup_latency_usec, cpu); > > n->avg += wakeup_latency_usec; > n->wakeup_nr++; > } > > /* Dump the Splay-tree. */ > while (sroot.sp_root) { > n = container_of(sroot.sp_root, struct sched_waking, node); > /* fprintf(stdout, "name: %30s pid: %10d woken- > up %5d\twakeup-latency: min %5d\tmax %5d\tavg %5d\n", */ > /* n->comm, n->pid, n->wakeup_nr, */ > /* n->min, n->max, n->avg / n->wakeup_nr); */ > > total_waking += n->wakeup_nr; > splay_delete_init(&n->node, &sroot); > free(n); > } > > /* fprintf(stdout, "=== Total: %u ===\n", total_waking); */ > /* fprintf(stdout, "\tRun '%s %s | sort -nk 6' to sort by column 6.\n", > name, script); */ } > > > /* > * Requires: > * rcu:rcu_batch_start > * rcu:rcu_invoke_callback > * rcu:rcu_batch_end > */ > static void > perf_script_synchronize_rcu_latency(const char *name, FILE *file, const char > *script) { > char buf[4096] = { '\0' }; > char buf_1[4096] = { '\0' }; > long offset; > char *s; > int rv; > > while (1) { > rv = get_one_line(file, buf, sizeof(buf)); > offset = ftell(file); > > if (rv != EOF) { > s = strstr(buf, "rcu_batch_start:"); > if (s) { > int delta_time_usec; > int sec_0, usec_0; > int sec_1, usec_1; > int pid_0, pid_1; > int extra; > > /* > * rcuop/5-58 [007] d..1. 6111.808748: > rcu_batch_start: rcu_preempt CBs=23 bl=10 > */ > (void) sscanf(buf, "%*[^0-9]%d-%d", &pid_0, > &pid_0); > get_cpu_sec_usec_in_string(buf, &extra, > &sec_0, &usec_0); > > while (1) { > rv = get_one_line(file, buf_1, > sizeof(buf_1)); > if (rv == EOF) > break; > > /* Do not care what a string format is > on this step. */ > (void) sscanf(buf, "%*[^0-9]%d-%d", > &pid_1, &pid_1); > > /* > * rcuop/4-51 [007] d..1. > 6111.816758: rcu_batch_end: rcu_preempt CBs-invoked=1 idle=.... > */ > s = strstr(buf_1, "rcu_batch_end:"); > if (s && pid_0 == pid_1) > break; > > /* > * rcuop/1-29 [005] ..... > 6111.808745: rcu_invoke_callback: rcu_preempt rhp=0000000093881c60 > func=file_free_rcu.cfi_jt > */ > s = strstr(buf_1, > "rcu_invoke_callback:"); > if (!s || pid_0 != pid_1) > continue; > > s = strstr(buf_1, > "wakeme_after_rcu"); > if (s) { > > get_cpu_sec_usec_in_string(buf_1, &extra, &sec_1, &usec_1); > delta_time_usec = (sec_1 - > sec_0) * 1000000 + (usec_1 - usec_0); > fprintf(stdout, "{\n%s\n%s\n} > latency %d usec\n", buf, buf_1, delta_time_usec); > break; > } > } > } > > rv = fseek(file, offset, SEEK_SET); > if (rv) > fprintf(stdout, "fseek error !!!\n"); > } else { > break; > } > } > > } > > int main(int argc, char **argv) > { > FILE *file; > > file = open_perf_script_file(argv[1]); > if (file == NULL) { > fprintf(stdout, "%s:%d failed: specify a perf script file\n", > __func__, __LINE__); > exit(-1); > } > > /* perf_script_softirq_delay(file, 1000); */ > /* perf_script_softirq_duration(file, 500); */ > /* perf_script_hardirq_duration(file, 500); */ > /* perf_script_hardirq_stat(file); */ > /* perf_script_sched_waking_stat(argv[0], file, argv[1]); */ > /* perf_script_sched_wakeup_latency(argv[0], file, argv[1]); */ > perf_script_synchronize_rcu_latency(argv[0], file, argv[1]); > > return 0; > } > <snip> > > Running it as "./a.out app_launch_rcu_trace.txt" will produce below results: Thanks for the usage example. > <snip> > ... > { > <...>-29 [001] d..1. 21950.145313: rcu_batch_start: rcu_preempt > CBs=3613 bl=28 > <...>-29 [001] ..... 21950.152583: rcu_invoke_callback: rcu_preempt > rhp=000000008f162ca8 func=wakeme_after_rcu.cfi_jt > } latency 7270 usec > { > rcuop/5-58 [005] d..1. 21951.352767: rcu_batch_start: rcu_preempt > CBs=3 bl=10 > rcuop/5-58 [005] ..... 21951.352768: rcu_invoke_callback: rcu_preempt > rhp=00000000b995fac1 func=wakeme_after_rcu.cfi_jt > } latency 1 usec > { > rcuop/6-65 [007] d..1. 21951.804768: rcu_batch_start: rcu_preempt > CBs=5 bl=10 > rcuop/6-65 [007] ..... 21951.804769: rcu_invoke_callback: rcu_preempt > rhp=00000000b995fac1 func=wakeme_after_rcu.cfi_jt > } latency 1 usec > { > rcuop/7-72 [006] d..1. 21951.884774: rcu_batch_start: rcu_preempt > CBs=3517 bl=27 > rcuop/7-72 [006] ..... 21951.885979: rcu_invoke_callback: rcu_preempt > rhp=000000005119eccc func=wakeme_after_rcu.cfi_jt > } latency 1205 usec > { > rcuop/5-58 [007] d..1. 21951.912853: rcu_batch_start: rcu_preempt > CBs=193 bl=10 > rcuop/5-58 [007] ..... 21951.912975: rcu_invoke_callback: rcu_preempt > rhp=00000000b995fac1 func=wakeme_after_rcu.cfi_jt > } latency 122 usec > ... > <snip> > > now you have a pair. > > -- > Uladzislau Rezki
