1 /* This file is part of the Linux Trace Toolkit viewer
2 * Copyright (C) 2008 Pierre-Marc Fournier
4 * This program is free software; you can redistribute it and/or modify
5 * it under the terms of the GNU General Public License Version 2 as
6 * published by the Free Software Foundation;
8 * This program is distributed in the hope that it will be useful,
9 * but WITHOUT ANY WARRANTY; without even the implied warranty of
10 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
11 * GNU General Public License for more details.
13 * You should have received a copy of the GNU General Public License
14 * along with this program; if not, write to the Free Software
15 * Foundation, Inc., 59 Temple Place - Suite 330, Boston,
23 #include <lttv/lttv.h>
24 #include <lttv/option.h>
25 #include <lttv/module.h>
26 #include <lttv/hook.h>
27 #include <lttv/attribute.h>
28 #include <lttv/iattribute.h>
29 #include <lttv/stats.h>
30 #include <lttv/filter.h>
31 #include <lttv/print.h>
33 #include <ltt/event.h>
34 #include <ltt/trace.h>
48 static int depanalysis_range_pid
= -1;
49 static int depanalysis_range_pid_searching
= -1;
50 static int depanalysis_use_time
=0;
51 static int depanalysis_event_limit
= -1;
52 static int a_print_simple_summary
= 0;
53 static LttTime depanalysis_time1
, depanalysis_time2
;
54 static char *arg_t1_str
,*arg_t2_str
;
55 static int statedump_finished
= 0;
58 struct llev_state_info_irq
{
62 struct llev_state_info_softirq
{
66 struct llev_state_info_syscall
{
74 struct llev_state_info_syscall__open
{
78 struct llev_state_info_syscall__read
{
82 struct llev_state_info_syscall__poll
{
86 struct llev_state_info_preempted
{
90 struct hlev_state_info_blocked
{
92 unsigned char trap
; /* flag */
95 /* Garray of pointers to struct process_state that reflect the
96 * low-level state stack when respectively entering and exiting the blocked
99 GArray
*llev_state_entry
;
100 GArray
*llev_state_exit
;
102 int pid_exit
; /* FIXME: it's not pretty to have this here; find this info elsewhere */
108 struct hlev_state_info_blocked__open
{
112 struct hlev_state_info_blocked__read
{
116 struct hlev_state_info_blocked__poll
{
120 struct hlev_state_info_interrupted_irq
{
124 struct hlev_state_info_interrupted_softirq
{
128 struct summary_tree_node
{
130 GHashTable
*children
;
142 struct state_info llev_state_infos
[] = {
143 { "UNKNOWN", 0, { NULL
} },
144 { "RUNNING", 0, { NULL
} },
145 { "SYSCALL", sizeof(struct llev_state_info_syscall
), { NULL
} },
146 { "IRQ", sizeof(struct llev_state_info_irq
), { NULL
} },
147 { "SOFTIRQ", sizeof(struct llev_state_info_softirq
), { NULL
} },
148 { "TRAP", 0, { NULL
} },
149 { "PREEMPTED", sizeof(struct llev_state_info_preempted
), { NULL
} },
152 struct state_info hlev_state_infos
[] = {
153 { "UNKNOWN", 0, { "Total", "Unknown", NULL
} },
154 { "RUNNING", 0, { "Total", "Working", NULL
} },
155 { "BLOCKED", sizeof(struct hlev_state_info_blocked
), { "Total", "Blocked", NULL
} },
156 { "INTERRUPTED_IRQ", sizeof(struct hlev_state_info_interrupted_irq
), { "Total", "Interrupted", "IRQ", NULL
} },
157 { "INTERRUPTED_SOFTIRQ", sizeof(struct hlev_state_info_interrupted_softirq
), { "Total", "Interrupted", "SoftIRQ", NULL
} },
158 { "INTERRUPTED_CPU", 0, { "Total", "Interrupted", "Preempted", NULL
} },
159 { "INTERRUPTED_POST_BLOCK", 0, { "Total", "Interrupted", "Waiting schedule after blocking", NULL
} },
172 enum llev_syscall_substate
{
173 LLEV_SYSCALL__UNDEFINED
,
180 HLEV_EVENT_TRY_WAKEUP
=0,
187 HLEV_INTERRUPTED_IRQ
,
188 HLEV_INTERRUPTED_SOFTIRQ
,
189 HLEV_INTERRUPTED_CPU
,
190 HLEV_INTERRUPTED_POST_BLOCK
,
193 enum hlev_state_blocked
{
194 HLEV_BLOCKED__UNDEFINED
,
200 struct sstack_event
{
205 struct try_wakeup_event
{
206 int pid
; /* this sould be more precise avec pid may be reused */
208 struct process
*waker
;
211 struct process_state
{
220 struct process_with_state
{
221 struct process
*process
;
222 struct process_state state
;
225 #define PROCESS_STATE_STACK_SIZE 10
231 struct sstack
*stack
;
232 struct process_state
*llev_state_stack
[PROCESS_STATE_STACK_SIZE
];
234 struct process_state
*hlev_state
;
235 GArray
*hlev_history
;
238 static inline void *old_process_state_private_data(struct process
*p
)
240 return p
->llev_state_stack
[p
->stack_current
]->private;
243 static inline struct process_state
*process_find_state(struct process
*p
, enum llev_state st
)
247 for(i
=p
->stack
->array
->len
-1; i
>=0; i
--) {
248 struct sstack_item
*item
= g_array_index(p
->stack
->array
, struct sstack_item
*, i
);
250 struct process_with_state
*pwstate
= item
->data_val
;
251 if(pwstate
->state
.bstate
== st
) {
252 return &pwstate
->state
;
259 static int find_pos_in_stack(enum llev_state lls
, struct process
*p
)
262 for(i
=p
->stack_current
; i
>=0; i
--) {
263 if(p
->llev_state_stack
[i
]->bstate
== lls
)
270 static struct process_state
*find_in_stack(enum llev_state lls
, struct process
*p
)
274 result
= find_pos_in_stack(lls
, p
);
277 return p
->llev_state_stack
[result
];
283 /* called back from sstack on deletion of a data_val which is
284 * a struct process_with_state
287 static void delete_data_val(struct process_with_state
*pwstate
)
289 // FIXME: Free this also
290 //g_free(pwstate->state.private);
292 // FIXME: this is really ugly. Don't free the pwstate if the state is LLEV_RUNNING.
293 // LLEV_RUNNING is a special case that's being processed and deleted immediately after
294 // being inserted on the sstack, to prevent state begin accumulated because it couldn't
295 // be processed before the end of the trace. If we free the state, we get invalid memory
296 // reads when looking at it on the state_stack.
297 //if(pwstate->state.bstate != LLEV_RUNNING)
301 inline void print_time(LttTime t
)
303 //printf("%lu.%lu", t.tv_sec, t.tv_nsec);
305 f
= (double)t
.tv_sec
+ ((double)t
.tv_nsec
)/1000000000.0;
309 static struct sstack_item
*prepare_push_item(struct process
*p
, enum llev_state st
, LttTime t
)
311 struct process_with_state
*pwstate
= g_malloc(sizeof(struct process_with_state
));
312 struct sstack_item
*item
;
314 int wait_for_pop
= 0;
316 if(st
== LLEV_SYSCALL
) {
317 /* We need to push LLEV_SYSCALL as wait_for_pop because it depends on some of
318 * its children. If we don't do this, it's going to get processed immediately
319 * by the sstack and we might miss some details about it that will come later.
324 item
= sstack_item_new_push(wait_for_pop
);
326 //printf("pushing in context of %d\n", p->pid);
328 pwstate
->process
= p
;
329 pwstate
->state
.bstate
= st
;
330 pwstate
->state
.time_begin
= t
;
331 pwstate
->state
.private = g_malloc(llev_state_infos
[st
].size_priv
);
333 item
->data_val
= pwstate
;
334 item
->delete_data_val
= (void (*)(void*))delete_data_val
;
339 static void *item_private(struct sstack_item
*item
)
341 struct process_with_state
*pwstate
= item
->data_val
;
342 return pwstate
->state
.private;
345 static void commit_item(struct process
*p
, struct sstack_item
*item
)
347 sstack_add_item(p
->stack
, item
);
350 static void old_process_push_llev_state(struct process
*p
, struct process_state
*pstate
)
352 if(++p
->stack_current
>= PROCESS_STATE_STACK_SIZE
) {
353 fprintf(stderr
, "depanalysis: internal process stack overflow\n");
357 p
->llev_state_stack
[p
->stack_current
] = pstate
;
360 static void live_complete_process_push_llev_state(struct process
*p
, enum llev_state st
, LttTime t
)
362 struct process_state
*pstate
= g_malloc(sizeof(struct process_state
));
365 pstate
->time_begin
= t
;
366 pstate
->private = g_malloc(llev_state_infos
[st
].size_priv
);
368 old_process_push_llev_state(p
, pstate
);
371 static void prepare_pop_item_commit_nocheck(struct process
*p
, enum llev_state st
, LttTime t
)
373 struct process_with_state
*pwstate
;
374 struct sstack_item
*item
= sstack_item_new_pop();
378 if(p
->stack
->pushes
->len
> 0)
379 push_idx
= g_array_index(p
->stack
->pushes
, int, p
->stack
->pushes
->len
-1);
384 pwstate
= g_array_index(p
->stack
->array
, struct sstack_item
*, push_idx
)->data_val
;
385 pwstate
->process
= p
;
386 pwstate
->state
.time_end
= t
;
387 item
->data_val
= pwstate
;
388 /* don't set delete_data_val because we use the same pwstate as push, and we don't want to free it twice */
392 pwstate
= g_malloc(sizeof(struct process_with_state
));
393 pwstate
->process
= p
;
394 item
->data_val
= pwstate
;
395 pwstate
->state
.time_end
= t
;
396 pwstate
->state
.bstate
= st
;
399 sstack_add_item(p
->stack
, item
);
403 static void prepare_pop_item_commit(struct process
*p
, enum llev_state st
, LttTime t
)
405 struct process_with_state
*pwstate
;
406 struct sstack_item
*item
= sstack_item_new_pop();
410 if(p
->stack
->pushes
->len
> 0)
411 push_idx
= g_array_index(p
->stack
->pushes
, int, p
->stack
->pushes
->len
-1);
416 /* FIXME: ugly workaround for kernel bug that generates two kernel_arch_syscall_exit on fork.
417 * The bug only occurs upon creation of new processes. But these processes always have
418 * a LLEV_RUNNING at index 0. */
419 if(push_idx
>= p
->stack
->array
->len
)
422 pwstate
= g_array_index(p
->stack
->array
, struct sstack_item
*, push_idx
)->data_val
;
424 if(pwstate
->state
.bstate
!= st
) {
425 /* FIXME: ugly workaround for kernel bug that generates two kernel_arch_syscall_exit on fork */
426 if(st
!= LLEV_SYSCALL
) {
427 printf("bad pop! at ");
430 print_stack(p
->stack
);
434 /* case where we have a double syscall_exit */
440 prepare_pop_item_commit_nocheck(p
, st
, t
);
444 static int try_pop_blocked_llev_preempted(struct process
*p
, LttTime t
)
447 struct process_with_state
*pwstate
;
449 if(p
->stack
->pushes
->len
> 0)
450 push_idx
= g_array_index(p
->stack
->pushes
, int, p
->stack
->pushes
->len
-1);
455 pwstate
= g_array_index(p
->stack
->array
, struct sstack_item
*, push_idx
)->data_val
;
457 if(!(pwstate
->state
.bstate
== LLEV_PREEMPTED
&& ((struct llev_state_info_preempted
*)pwstate
->state
.private)->prev_state
> 0)) {
458 //printf("double try wake up\n");
463 prepare_pop_item_commit_nocheck(p
, LLEV_PREEMPTED
, t
);
467 static void old_process_pop_llev_state(struct process
*p
, struct process_state
*pstate
)
469 /* Ensure we are really popping the current state */
470 /* FIXME: pstate->bstate is uninitialized? */
471 // Commenting because it does not work. The way things work now, this check cannot work.
472 //if(p->llev_state_stack[p->stack_current]->bstate != LLEV_UNKNOWN && p->llev_state_stack[p->stack_current]->bstate != pstate->bstate) {
473 // printf("ERROR! bad pop!\n");
477 /* Actually change the that position */
478 if(p
->stack_current
>= 0)
481 /* If stack empty, we must put something in it */
482 if(p
->stack_current
== -1) {
483 if(pstate
->bstate
== LLEV_SYSCALL
) {
484 //process_push_llev_state(p, LLEV_RUNNING, pstate->time_end);
485 live_complete_process_push_llev_state(p
, LLEV_RUNNING
, pstate
->time_end
);
488 live_complete_process_push_llev_state(p
, LLEV_UNKNOWN
, pstate
->time_end
);
493 static GHashTable
*process_hash_table
;
494 static GHashTable
*syscall_table
;
495 static GHashTable
*irq_table
;
496 static GHashTable
*softirq_table
;
498 /* Insert the hooks before and after each trace and tracefile, and for each
499 event. Print a global header. */
503 static GString
*a_string
;
505 static gboolean
write_traceset_header(void *hook_data
, void *call_data
)
507 LttvTracesetContext
*tc
= (LttvTracesetContext
*)call_data
;
509 g_info("Traceset header");
511 /* Print the trace set header */
512 g_info(a_file
,"Trace set contains %d traces\n\n",
513 lttv_traceset_number(tc
->ts
));
518 GArray
*oldstyle_stack_to_garray(struct process_state
**oldstyle_stack
, int current
)
523 retval
= g_array_new(FALSE
, FALSE
, sizeof(struct process_state
*));
525 for(i
=0; i
<current
; i
++) {
526 g_array_append_val(retval
, oldstyle_stack
[i
]);
532 static void update_hlev_state(struct process
*p
, LttTime t
)
536 enum hlev_state new_hlev
;
538 for(i
=p
->stack_current
; i
>=0; i
--) {
540 st
= p
->llev_state_stack
[i
]->bstate
;
542 if(st
== LLEV_RUNNING
|| st
== LLEV_TRAP
|| st
== LLEV_SYSCALL
) {
543 new_hlev
= HLEV_RUNNING
;
546 else if(st
== LLEV_IRQ
) {
547 new_hlev
= HLEV_INTERRUPTED_IRQ
;
550 else if(st
== LLEV_SOFTIRQ
) {
551 new_hlev
= HLEV_INTERRUPTED_SOFTIRQ
;
554 else if(st
== LLEV_PREEMPTED
) {
555 int prev_state
= ((struct llev_state_info_preempted
*) old_process_state_private_data(p
))->prev_state
;
557 if(prev_state
== 0) {
558 new_hlev
= HLEV_INTERRUPTED_CPU
;
560 else if(prev_state
== -1) {
561 new_hlev
= HLEV_INTERRUPTED_POST_BLOCK
;
564 new_hlev
= HLEV_BLOCKED
;
568 else if(st
== LLEV_UNKNOWN
) {
569 new_hlev
= HLEV_UNKNOWN
;
577 /* If no state change, do nothing */
578 if(p
->hlev_state
!= NULL
&& new_hlev
== p
->hlev_state
->bstate
) {
582 p
->hlev_state
->time_end
= t
;
583 /* This check is here because we initially put HLEV_UNKNOWN as hlev state, but in the case
584 * of processes newly created, it is immediately replaced by HLEV_BLOCKED. In order to avoid
585 * having a UNKNOWN state of duration 0 in the summary, we don't add it. This isn't as elegant
588 if(ltt_time_compare(p
->hlev_state
->time_begin
, p
->hlev_state
->time_end
) != 0)
589 g_array_append_val(p
->hlev_history
, p
->hlev_state
);
590 p
->hlev_state
= g_malloc(sizeof(struct process_state
));
591 p
->hlev_state
->bstate
= new_hlev
;
592 p
->hlev_state
->time_begin
= t
;
593 p
->hlev_state
->private = g_malloc(hlev_state_infos
[new_hlev
].size_priv
);
595 //printf("depanalysis: now at hlev state %s\n", hlev_state_infos[new_hlev].name);
597 /* Set private data */
598 switch(p
->hlev_state
->bstate
) {
604 struct hlev_state_info_blocked
*hlev_blocked_private
= p
->hlev_state
->private;
605 //struct process_state *ps = find_in_stack(LLEV_SYSCALL, p);
606 int syscall_pos
= find_pos_in_stack(LLEV_SYSCALL
, p
);
607 int trap_pos
= find_pos_in_stack(LLEV_TRAP
, p
);
610 hlev_blocked_private
->syscall_id
= 1;
611 hlev_blocked_private
->trap
= 0;
612 hlev_blocked_private
->substate
= HLEV_BLOCKED__UNDEFINED
;
613 hlev_blocked_private
->private = NULL
;
614 hlev_blocked_private
->llev_state_entry
= oldstyle_stack_to_garray(p
->llev_state_stack
, p
->stack_current
);
615 hlev_blocked_private
->llev_state_exit
= NULL
;
617 //g_assert(syscall_pos >= 0 || trap_pos >= 0);
619 if(trap_pos
> syscall_pos
) {
620 hlev_blocked_private
->trap
= 1;
623 /* initial value, may be changed below */
624 hlev_blocked_private
->substate
= HLEV_BLOCKED__UNDEFINED
;
626 if(syscall_pos
>= 0) {
627 struct process_state
*ps
= p
->llev_state_stack
[syscall_pos
];
628 struct llev_state_info_syscall
*llev_syscall_private
= (struct llev_state_info_syscall
*) ps
->private;
629 hlev_blocked_private
->syscall_id
= llev_syscall_private
->syscall_id
;
631 if(llev_syscall_private
->substate
== LLEV_SYSCALL__OPEN
) {
632 struct llev_state_info_syscall__open
*llev_syscall_open_private
;
633 struct hlev_state_info_blocked__open
*hlev_blocked_open_private
;
634 llev_syscall_open_private
= llev_syscall_private
->private;
635 hlev_blocked_private
->substate
= HLEV_BLOCKED__OPEN
;
636 hlev_blocked_open_private
= g_malloc(sizeof(struct hlev_state_info_blocked__open
));
637 hlev_blocked_private
->private = hlev_blocked_open_private
;
638 hlev_blocked_open_private
->filename
= llev_syscall_open_private
->filename
;
640 //printf("depanalysis: blocked in an open!\n");
642 else if(llev_syscall_private
->substate
== LLEV_SYSCALL__READ
) {
643 struct llev_state_info_syscall__read
*llev_syscall_read_private
;
644 struct hlev_state_info_blocked__read
*hlev_blocked_read_private
;
645 llev_syscall_read_private
= llev_syscall_private
->private;
646 hlev_blocked_private
->substate
= HLEV_BLOCKED__READ
;
647 hlev_blocked_read_private
= g_malloc(sizeof(struct hlev_state_info_blocked__read
));
648 hlev_blocked_private
->private = hlev_blocked_read_private
;
649 hlev_blocked_read_private
->filename
= llev_syscall_read_private
->filename
;
651 //printf("depanalysis: blocked in a read!\n");
653 else if(llev_syscall_private
->substate
== LLEV_SYSCALL__POLL
) {
654 struct llev_state_info_syscall__poll
*llev_syscall_poll_private
;
655 struct hlev_state_info_blocked__poll
*hlev_blocked_poll_private
;
656 llev_syscall_poll_private
= llev_syscall_private
->private;
657 hlev_blocked_private
->substate
= HLEV_BLOCKED__POLL
;
658 hlev_blocked_poll_private
= g_malloc(sizeof(struct hlev_state_info_blocked__poll
));
659 hlev_blocked_private
->private = hlev_blocked_poll_private
;
660 hlev_blocked_poll_private
->filename
= llev_syscall_poll_private
->filename
;
662 //printf("depanalysis: blocked in a read!\n");
666 hlev_blocked_private
->syscall_id
= -1;
671 case HLEV_INTERRUPTED_IRQ
: {
672 struct hlev_state_info_interrupted_irq
*sinfo
= p
->hlev_state
->private;
673 struct process_state
*ps
= find_in_stack(LLEV_IRQ
, p
);
677 sinfo
->irq
= ((struct llev_state_info_irq
*) ps
->private)->irq
;
680 case HLEV_INTERRUPTED_SOFTIRQ
: {
681 struct hlev_state_info_interrupted_softirq
*sinfo
= p
->hlev_state
->private;
682 struct process_state
*ps
= find_in_stack(LLEV_SOFTIRQ
, p
);
686 sinfo
->softirq
= ((struct llev_state_info_softirq
*) ps
->private)->softirq
;
694 static gint
compare_summary_tree_node_times(gconstpointer a
, gconstpointer b
)
696 struct summary_tree_node
*n1
= (struct summary_tree_node
*) a
;
697 struct summary_tree_node
*n2
= (struct summary_tree_node
*) b
;
699 return ltt_time_compare(n2
->duration
, n1
->duration
);
702 /* Print an item of the simple summary tree, and recurse, printing its children.
704 * If depth == -1, this is the root: we don't print a label, we only recurse into
708 static void print_summary_item(struct summary_tree_node
*node
, int depth
)
713 printf("\t%*s (", strlen(node
->name
)+2*depth
, node
->name
);
714 print_time(node
->duration
);
715 printf(") <%d>\n", node
->id_for_episodes
);
721 vals
= g_hash_table_get_values(node
->children
);
723 /* sort the values */
724 vals
= g_list_sort(vals
, compare_summary_tree_node_times
);
727 print_summary_item((struct summary_tree_node
*)vals
->data
, depth
+1);
731 /* we must free the list returned by g_hash_table_get_values() */
735 static inline void print_irq(int irq
)
737 printf("IRQ %d [%s]", irq
, g_quark_to_string(g_hash_table_lookup(irq_table
, &irq
)));
740 static inline void print_softirq(int softirq
)
742 printf("SoftIRQ %d [%s]", softirq
, g_quark_to_string(g_hash_table_lookup(softirq_table
, &softirq
)));
745 static inline void print_pid(int pid
)
747 struct process
*event_process_info
= g_hash_table_lookup(process_hash_table
, &pid
);
751 if(event_process_info
== NULL
)
754 pname
= g_quark_to_string(event_process_info
->name
);
755 printf("%d [%s]", pid
, pname
);
758 static void modify_path_with_private(GArray
*path
, struct process_state
*pstate
)
760 //GString tmps = g_string_new("");
763 // FIXME: fix this leak
764 switch(pstate
->bstate
) {
765 case HLEV_INTERRUPTED_IRQ
:
766 asprintf(&tmps
, "IRQ %d [%s]", ((struct hlev_state_info_interrupted_irq
*)pstate
->private)->irq
, g_quark_to_string(g_hash_table_lookup(irq_table
, &((struct hlev_state_info_interrupted_irq
*)pstate
->private)->irq
)));
767 g_array_append_val(path
, tmps
);
769 case HLEV_INTERRUPTED_SOFTIRQ
:
770 asprintf(&tmps
, "SoftIRQ %d [%s]", ((struct hlev_state_info_interrupted_softirq
*)pstate
->private)->softirq
, g_quark_to_string(g_hash_table_lookup(softirq_table
, &((struct hlev_state_info_interrupted_softirq
*)pstate
->private)->softirq
)));
771 g_array_append_val(path
, tmps
);
774 struct hlev_state_info_blocked
*hlev_blocked_private
= (struct hlev_state_info_blocked
*)pstate
->private;
776 if(hlev_blocked_private
->trap
) {
778 g_array_append_val(path
, ptr
);
781 if(hlev_blocked_private
->syscall_id
== -1) {
782 char *ptr
= "Userspace";
783 g_array_append_val(path
, ptr
);
786 asprintf(&tmps
, "Syscall %d [%s]", hlev_blocked_private
->syscall_id
, g_quark_to_string(g_hash_table_lookup(syscall_table
, &hlev_blocked_private
->syscall_id
)));
787 g_array_append_val(path
, tmps
);
790 if(((struct hlev_state_info_blocked
*)pstate
->private)->substate
== HLEV_BLOCKED__OPEN
) {
791 char *str
= g_quark_to_string(((struct hlev_state_info_blocked__open
*)((struct hlev_state_info_blocked
*)pstate
->private)->private)->filename
);
792 g_array_append_val(path
, str
);
794 else if(((struct hlev_state_info_blocked
*)pstate
->private)->substate
== HLEV_BLOCKED__READ
) {
796 asprintf(&str
, "%s", g_quark_to_string(((struct hlev_state_info_blocked__read
*)((struct hlev_state_info_blocked
*)pstate
->private)->private)->filename
));
797 g_array_append_val(path
, str
);
798 /* FIXME: this must be freed at some point */
801 else if(((struct hlev_state_info_blocked
*)pstate
->private)->substate
== HLEV_BLOCKED__POLL
) {
803 asprintf(&str
, "%s", g_quark_to_string(((struct hlev_state_info_blocked__poll
*)((struct hlev_state_info_blocked
*)pstate
->private)->private)->filename
));
804 g_array_append_val(path
, str
);
805 /* FIXME: this must be freed at some point */
813 void print_stack_garray_horizontal(GArray
*stack
)
815 /* FIXME: this function doesn't work if we delete the states as we process them because we
816 * try to read those states here to print the low level stack.
820 for(i
=0; i
<stack
->len
; i
++) {
821 struct process_state
*pstate
= g_array_index(stack
, struct process_state
*, i
);
822 printf("%s", llev_state_infos
[pstate
->bstate
].name
);
824 if(pstate
->bstate
== LLEV_SYSCALL
) {
825 struct llev_state_info_syscall
*llev_syscall_private
= pstate
->private;
826 printf(" %d [%s]", llev_syscall_private
->syscall_id
, g_quark_to_string(g_hash_table_lookup(syscall_table
, &llev_syscall_private
->syscall_id
)));
834 static int dicho_search_state_ending_after(struct process
*p
, LttTime t
)
837 int over
= p
->hlev_history
->len
-1;
838 struct process_state
*pstate
;
844 /* If the last element is smaller or equal than the time we are searching for,
847 pstate
= g_array_index(p
->hlev_history
, struct process_state
*, over
);
848 if(ltt_time_compare(pstate
->time_end
, t
) <= 0) {
851 /* no need to check for the equal case */
853 pstate
= g_array_index(p
->hlev_history
, struct process_state
*, under
);
854 result
= ltt_time_compare(pstate
->time_end
, t
);
856 /* trivial match at the first element if it is greater or equal
857 * than the time we want
865 dicho
= (under
+over
)/2;
866 pstate
= g_array_index(p
->hlev_history
, struct process_state
*, dicho
);
867 result
= ltt_time_compare(pstate
->time_end
, t
);
872 else if(result
== 1) {
880 if(over
-under
== 1) {
881 /* we have converged */
888 /* FIXME: this shouldn't be based on pids in case of reuse
889 * FIXME: should add a list of processes used to avoid loops
892 static struct process_state
*find_state_ending_after(int pid
, LttTime t
)
898 p
= g_hash_table_lookup(process_hash_table
, &pid
);
902 result
= dicho_search_state_ending_after(p
, t
);
907 return g_array_index(p
->hlev_history
, struct process_state
*, result
);
910 static void print_indent(int offset
)
915 printf("%*s", 8, "");
916 for (i
= 3; i
< offset
; i
++) {
918 printf("%*s", 4, "");
921 printf("%*s", 4*offset
, "");
924 static void print_delay_pid(int pid
, LttTime t1
, LttTime t2
, int offset
)
929 p
= g_hash_table_lookup(process_hash_table
, &pid
);
933 i
= dicho_search_state_ending_after(p
, t1
);
934 for(; i
<p
->hlev_history
->len
; i
++) {
935 struct process_state
*pstate
= g_array_index(p
->hlev_history
, struct process_state
*, i
);
936 if(ltt_time_compare(pstate
->time_end
, t2
) > 0)
939 if(pstate
->bstate
== HLEV_BLOCKED
) {
940 struct hlev_state_info_blocked
*state_private_blocked
;
941 state_private_blocked
= pstate
->private;
942 struct process_state
*state_unblocked
;
944 print_indent(offset
);
945 printf("--> Blocked in ");
946 print_stack_garray_horizontal(state_private_blocked
->llev_state_entry
);
949 print_time(pstate
->time_begin
);
951 print_time(pstate
->time_end
);
953 printf(", dur: %f)\n", 1e-9*ltt_time_to_double(ltt_time_sub(pstate
->time_end
, pstate
->time_begin
)));
955 state_unblocked
= find_state_ending_after(state_private_blocked
->pid_exit
, state_private_blocked
->time_woken
);
956 if(state_unblocked
) {
957 if(state_unblocked
->bstate
== HLEV_INTERRUPTED_IRQ
) {
958 struct hlev_state_info_interrupted_irq
*priv
= state_unblocked
->private;
959 /* if in irq or softirq, we don't care what the waking process was doing because they are asynchroneous events */
960 print_indent(offset
);
961 printf("--- Woken up by an IRQ: ");
962 print_irq(priv
->irq
);
965 else if(state_unblocked
->bstate
== HLEV_INTERRUPTED_SOFTIRQ
) {
966 struct hlev_state_info_interrupted_softirq
*priv
= state_unblocked
->private;
967 print_indent(offset
);
968 printf("--- Woken up by a SoftIRQ: ");
969 print_softirq(priv
->softirq
);
976 if(ltt_time_compare(t1prime
, pstate
->time_begin
) < 0)
977 t1prime
= pstate
->time_begin
;
978 if(ltt_time_compare(t2prime
, pstate
->time_end
) > 0)
979 t2prime
= pstate
->time_end
;
981 print_delay_pid(state_private_blocked
->pid_exit
, t1prime
, t2prime
, offset
+1);
982 print_indent(offset
);
983 printf("--- Woken up in context of ");
984 print_pid(state_private_blocked
->pid_exit
);
985 if(state_private_blocked
->llev_state_exit
) {
986 print_stack_garray_horizontal(state_private_blocked
->llev_state_exit
);
990 printf(" in high-level state %s", hlev_state_infos
[state_unblocked
->bstate
].name
);
995 print_indent(offset
);
996 printf("Weird... cannot find in what state the waker (%d) was\n", state_private_blocked
->pid_exit
);
1000 //print_delay_pid(state_private_blocked->pid_exit, pstate->time_start, pstate->time_end);
1001 //printf("\t\t Woken up in context of %d: ", state_private_blocked->pid_exit);
1002 //if(state_private_blocked->llev_state_exit) {
1003 // print_stack_garray_horizontal(state_private_blocked->llev_state_exit);
1004 // printf("here3 (%d)\n", state_private_blocked->llev_state_exit->len);
1007 // printf("the private_blocked %p had a null exit stack\n", state_private_blocked);
1013 static void print_range_critical_path(int process
, LttTime t1
, LttTime t2
)
1015 printf("Critical path for requested range:\n");
1016 printf("Final process is %d\n", process
);
1017 print_delay_pid(process
, t1
, t2
, 2);
1021 * output legend example:
1023 * --> Blocked in RUNNING, SYSCALL NNN [syscall_name]
1024 * | ---> Blocked in RUNNING, SYSCALL NNN [syscall_name]
1025 * | | --> Blocked in RUNNING, SYSCALL [syscall_name]
1026 * | | --- Woken up by an IRQ: IRQ 0 [timer]
1027 * | --- Woken up in context of PID [appname] in high-level state RUNNING
1028 * --- Woken up in context of PID [appname] in high-level state RUNNING
1031 static void print_process_critical_path_summary()
1033 struct process
*pinfo
;
1037 pinfos
= g_hash_table_get_values(process_hash_table
);
1038 if(pinfos
== NULL
) {
1039 fprintf(stderr
, "error: no process found\n");
1043 printf("Process Critical Path Summary:\n");
1046 struct summary_tree_node base_node
= { children
: NULL
};
1048 struct process_state
*hlev_state_cur
;
1050 pinfo
= (struct process
*)pinfos
->data
;
1051 if (depanalysis_range_pid_searching
!= -1 && pinfo
->pid
!= depanalysis_range_pid_searching
)
1053 printf("\tProcess %d [%s]\n", pinfo
->pid
, g_quark_to_string(pinfo
->name
));
1055 if(pinfo
->hlev_history
->len
< 1)
1058 print_delay_pid(pinfo
->pid
, g_array_index(pinfo
->hlev_history
, struct process_state
*, 0)->time_begin
, g_array_index(pinfo
->hlev_history
, struct process_state
*, pinfo
->hlev_history
->len
- 1)->time_end
, 2);
1063 pinfos
= pinfos
->next
;
1069 gint
compare_states_length(gconstpointer a
, gconstpointer b
)
1071 struct process_state
**s1
= (struct process_state
**)a
;
1072 struct process_state
**s2
= (struct process_state
**)b
;
1075 val
= ltt_time_compare(ltt_time_sub((*s2
)->time_end
, (*s2
)->time_begin
), ltt_time_sub((*s1
)->time_end
, (*s1
)->time_begin
));
1079 static void print_simple_summary(void)
1081 struct process
*pinfo
;
1083 GList
*pinfos_first
;
1085 int id_for_episodes
= 0;
1087 if (!a_print_simple_summary
)
1090 /* we save all the nodes here to print the episodes table quickly */
1091 GArray
*all_nodes
= g_array_new(FALSE
, FALSE
, sizeof(struct summary_tree_node
*));
1093 pinfos_first
= g_hash_table_get_values(process_hash_table
);
1094 if(pinfos_first
== NULL
) {
1095 fprintf(stderr
, "error: no processes found\n");
1098 pinfos
= pinfos_first
;
1100 printf("Simple summary:\n");
1102 /* For each process */
1104 struct summary_tree_node base_node
= { children
: NULL
, name
: "Root" };
1106 struct process_state
*hlev_state_cur
;
1108 pinfo
= (struct process
*)pinfos
->data
;
1109 printf("\tProcess %d [%s]\n", pinfo
->pid
, g_quark_to_string(pinfo
->name
));
1111 /* For each state in the process history */
1112 for(i
=0; i
<pinfo
->hlev_history
->len
; i
++) {
1113 struct process_state
*pstate
= g_array_index(pinfo
->hlev_history
, struct process_state
*, i
);
1114 struct summary_tree_node
*node_cur
= &base_node
;
1115 GArray
*tree_path_garray
;
1117 /* Modify the path based on private data */
1118 tree_path_garray
= g_array_new(FALSE
, FALSE
, sizeof(char *));
1121 char **tree_path_cur2
= hlev_state_infos
[pstate
->bstate
].tree_path
;
1122 while(*tree_path_cur2
) {
1126 g_array_append_vals(tree_path_garray
, hlev_state_infos
[pstate
->bstate
].tree_path
, count
);
1128 modify_path_with_private(tree_path_garray
, pstate
);
1130 /* Walk the path, adding the nodes to the summary */
1131 for(j
=0; j
<tree_path_garray
->len
; j
++) {
1132 struct summary_tree_node
*newnode
;
1133 GQuark componentquark
;
1135 /* Have a path component we must follow */
1136 if(!node_cur
->children
) {
1137 /* must create the hash table for the children */
1138 node_cur
->children
= g_hash_table_new(g_int_hash
, g_int_equal
);
1141 /* try to get the node for the next component */
1142 componentquark
= g_quark_from_string(g_array_index(tree_path_garray
, char *, j
));
1143 newnode
= g_hash_table_lookup(node_cur
->children
, &componentquark
);
1144 if(newnode
== NULL
) {
1145 newnode
= g_malloc(sizeof(struct summary_tree_node
));
1146 newnode
->children
= NULL
;
1147 newnode
->name
= g_array_index(tree_path_garray
, char *, j
);
1148 newnode
->duration
= ltt_time_zero
;
1149 newnode
->id_for_episodes
= id_for_episodes
++;
1150 newnode
->episodes
= g_array_new(FALSE
, FALSE
, sizeof(struct process_state
*));
1151 g_hash_table_insert(node_cur
->children
, &componentquark
, newnode
);
1153 g_array_append_val(all_nodes
, newnode
);
1157 node_cur
->duration
= ltt_time_add(node_cur
->duration
, ltt_time_sub(pstate
->time_end
, pstate
->time_begin
));
1158 g_array_append_val(node_cur
->episodes
, pstate
);
1162 /* print the summary */
1163 print_summary_item(&base_node
, -1);
1168 pinfos
= pinfos
->next
;
1175 printf("Episode list\n");
1176 pinfos
= pinfos_first
;
1178 /* For all the nodes of the Simple summary tree */
1179 for(i
=0; i
<all_nodes
->len
; i
++) {
1180 struct summary_tree_node
*node
= (struct summary_tree_node
*)g_array_index(all_nodes
, struct summary_tree_node
*, i
);
1182 /* Sort the episodes from longest to shortest */
1183 g_array_sort(node
->episodes
, compare_states_length
);
1185 printf("\tNode id: <%d>\n", node
->id_for_episodes
);
1186 /* For each episode of the node */
1187 for(j
=0; j
<node
->episodes
->len
; j
++) {
1188 struct process_state
*st
= g_array_index(node
->episodes
, struct process_state
*, j
);
1191 print_time(st
->time_begin
);
1193 print_time(st
->time_end
);
1194 printf(" (%f)\n", 1e-9*ltt_time_to_double(ltt_time_sub(st
->time_end
,st
->time_begin
)));
1199 static void print_simple_summary_pid_range(int pid
, LttTime t1
, LttTime t2
)
1201 struct process
*pinfo
;
1203 int id_for_episodes
= 0;
1205 /* we save all the nodes here to print the episodes table quickly */
1206 GArray
*all_nodes
= g_array_new(FALSE
, FALSE
, sizeof(struct summary_tree_node
*));
1208 pinfo
= g_hash_table_lookup(process_hash_table
, &pid
);
1211 struct summary_tree_node base_node
= { children
: NULL
, name
: "Root" };
1213 struct process_state
*hlev_state_cur
;
1215 printf("\tProcess %d [%s]\n", pinfo
->pid
, g_quark_to_string(pinfo
->name
));
1217 /* For each state in the process history */
1218 for(i
=0; i
<pinfo
->hlev_history
->len
; i
++) {
1219 struct process_state
*pstate
= g_array_index(pinfo
->hlev_history
, struct process_state
*, i
);
1220 struct summary_tree_node
*node_cur
= &base_node
;
1221 GArray
*tree_path_garray
;
1223 if(ltt_time_compare(pstate
->time_end
, t1
) < 0)
1226 if(ltt_time_compare(pstate
->time_end
, t2
) > 0)
1229 /* Modify the path based on private data */
1230 tree_path_garray
= g_array_new(FALSE
, FALSE
, sizeof(char *));
1233 char **tree_path_cur2
= hlev_state_infos
[pstate
->bstate
].tree_path
;
1234 while(*tree_path_cur2
) {
1238 g_array_append_vals(tree_path_garray
, hlev_state_infos
[pstate
->bstate
].tree_path
, count
);
1240 modify_path_with_private(tree_path_garray
, pstate
);
1242 /* Walk the path, adding the nodes to the summary */
1243 for(j
=0; j
<tree_path_garray
->len
; j
++) {
1244 struct summary_tree_node
*newnode
;
1245 GQuark componentquark
;
1247 /* Have a path component we must follow */
1248 if(!node_cur
->children
) {
1249 /* must create the hash table for the children */
1250 node_cur
->children
= g_hash_table_new(g_int_hash
, g_int_equal
);
1253 /* try to get the node for the next component */
1254 componentquark
= g_quark_from_string(g_array_index(tree_path_garray
, char *, j
));
1255 newnode
= g_hash_table_lookup(node_cur
->children
, &componentquark
);
1256 if(newnode
== NULL
) {
1257 newnode
= g_malloc(sizeof(struct summary_tree_node
));
1258 newnode
->children
= NULL
;
1259 newnode
->name
= g_array_index(tree_path_garray
, char *, j
);
1260 newnode
->duration
= ltt_time_zero
;
1261 newnode
->id_for_episodes
= id_for_episodes
++;
1262 newnode
->episodes
= g_array_new(FALSE
, FALSE
, sizeof(struct process_state
*));
1263 g_hash_table_insert(node_cur
->children
, &componentquark
, newnode
);
1265 g_array_append_val(all_nodes
, newnode
);
1269 node_cur
->duration
= ltt_time_add(node_cur
->duration
, ltt_time_sub(pstate
->time_end
, pstate
->time_begin
));
1270 g_array_append_val(node_cur
->episodes
, pstate
);
1274 /* print the summary */
1275 print_summary_item(&base_node
, -1);
1282 printf("Episode list\n");
1284 /* For all the nodes of the Simple summary tree */
1285 for(i
=0; i
<all_nodes
->len
; i
++) {
1286 struct summary_tree_node
*node
= (struct summary_tree_node
*)g_array_index(all_nodes
, struct summary_tree_node
*, i
);
1288 /* Sort the episodes from longest to shortest */
1289 g_array_sort(node
->episodes
, compare_states_length
);
1291 printf("\tNode id: <%d>\n", node
->id_for_episodes
);
1292 /* For each episode of the node */
1293 for(j
=0; j
<node
->episodes
->len
; j
++) {
1294 struct process_state
*st
= g_array_index(node
->episodes
, struct process_state
*, j
);
1297 print_time(st
->time_begin
);
1299 print_time(st
->time_end
);
1300 printf(" (%f)\n", 1e-9*ltt_time_to_double(ltt_time_sub(st
->time_end
,st
->time_begin
)));
1305 static void flush_process_sstacks(void)
1309 pinfos
= g_hash_table_get_values(process_hash_table
);
1311 struct process
*pinfo
= (struct process
*)pinfos
->data
;
1313 sstack_force_flush(pinfo
->stack
);
1315 pinfos
= pinfos
->next
;
1318 g_list_free(pinfos
);
1321 struct family_item
{
1326 void print_range_reports(int pid
, LttTime t1
, LttTime t2
)
1328 GArray
*family
= g_array_new(FALSE
, FALSE
, sizeof(struct family_item
));
1331 /* reconstruct the parental sequence */
1333 struct process
*pinfo
;
1334 struct family_item fi
;
1337 pinfo
= g_hash_table_lookup(process_hash_table
, &pid
);
1342 cur_beg
= g_array_index(pinfo
->hlev_history
, struct process_state
*, 0)->time_begin
;
1343 fi
.creation
= cur_beg
;
1344 g_array_append_val(family
, fi
);
1346 if(ltt_time_compare(cur_beg
, t1
) == -1) {
1347 /* current pid starts before the interesting time */
1350 if(pinfo
->parent
== -1) {
1351 printf("unable to go back, we don't know the parent of %d\n", fi
.pid
);
1354 /* else, we go on */
1355 pid
= pinfo
->parent
;
1359 printf("Simple summary for range:\n");
1360 for(i
=family
->len
-1; i
>=0; i
--) {
1361 LttTime iter_t1
, iter_t2
;
1362 int iter_pid
= g_array_index(family
, struct family_item
, i
).pid
;
1364 if(i
== family
->len
-1)
1367 iter_t1
= g_array_index(family
, struct family_item
, i
).creation
;
1372 iter_t2
= g_array_index(family
, struct family_item
, i
-1).creation
;
1374 printf("This section of summary concerns pid %d between ");
1375 print_time(iter_t1
);
1377 print_time(iter_t2
);
1379 print_simple_summary_pid_range(iter_pid
, iter_t1
, iter_t2
);
1381 print_range_critical_path(depanalysis_range_pid
, t1
, t2
);
1384 static gboolean
write_traceset_footer(void *hook_data
, void *call_data
)
1386 LttvTracesetContext
*tc
= (LttvTracesetContext
*)call_data
;
1388 g_info("TextDump traceset footer");
1390 g_info(a_file
,"End trace set\n\n");
1392 // if(LTTV_IS_TRACESET_STATS(tc)) {
1393 // lttv_stats_sum_traceset((LttvTracesetStats *)tc, ltt_time_infinite);
1394 // print_stats(a_file, (LttvTracesetStats *)tc);
1397 /* After processing all the events, we need to flush the sstacks
1398 * because some unfinished states may remain in them. We want them
1399 * event though there are incomplete.
1401 flush_process_sstacks();
1403 /* print the reports */
1404 print_simple_summary();
1405 print_process_critical_path_summary();
1406 if(depanalysis_use_time
== 3) {
1407 printf("depanalysis_use_time = %d\n", depanalysis_use_time
);
1408 if(depanalysis_range_pid
== -1 && depanalysis_range_pid_searching
>= 0)
1409 depanalysis_range_pid
= depanalysis_range_pid_searching
;
1411 if(depanalysis_range_pid
>= 0) {
1412 print_range_reports(depanalysis_range_pid
, depanalysis_time1
, depanalysis_time2
);
1415 printf("range critical path: could not find the end of the range\n");
1422 static gboolean
write_trace_header(void *hook_data
, void *call_data
)
1424 LttvTraceContext
*tc
= (LttvTraceContext
*)call_data
;
1426 LttSystemDescription
*system
= ltt_trace_system_description(tc
->t
);
1428 fprintf(a_file
," Trace from %s in %s\n%s\n\n",
1429 ltt_trace_system_description_node_name(system
),
1430 ltt_trace_system_description_domain_name(system
),
1431 ltt_trace_system_description_description(system
));
1438 static int write_event_content(void *hook_data
, void *call_data
)
1442 // LttvIAttribute *attributes = LTTV_IATTRIBUTE(lttv_global_attributes());
1444 LttvTracefileContext
*tfc
= (LttvTracefileContext
*)call_data
;
1446 LttvTracefileState
*tfs
= (LttvTracefileState
*)call_data
;
1450 guint cpu
= tfs
->cpu
;
1451 LttvTraceState
*ts
= (LttvTraceState
*)tfc
->t_context
;
1452 LttvProcessState
*process
= ts
->running_process
[cpu
];
1454 e
= ltt_tracefile_get_event(tfc
->tf
);
1456 lttv_event_to_string(e
, a_string
, TRUE
, 1, tfs
);
1459 g_string_append_printf(a_string
, " %s ",
1460 g_quark_to_string(process
->state
->s
));
1463 g_string_append_printf(a_string
,"\n");
1465 fputs(a_string
->str
, a_file
);
1469 static int field_get_value_int(struct LttEvent
*e
, struct marker_info
*info
, GQuark f
)
1471 struct marker_field
*marker_field
;
1474 for_each_marker_field(marker_field
, info
) {
1475 if (marker_field
->name
== f
) {
1481 return ltt_event_get_long_unsigned(e
, marker_field
);
1484 static char *field_get_value_string(struct LttEvent
*e
, struct marker_info
*info
, GQuark f
)
1486 struct marker_field
*marker_field
;
1489 for_each_marker_field(marker_field
, info
) {
1490 if (marker_field
->name
== f
) {
1496 return ltt_event_get_string(e
, marker_field
);
1499 void process_delayed_stack_action(struct process
*pinfo
, struct sstack_item
*item
)
1501 //printf("processing delayed stack action on pid %d at ", pinfo->pid);
1502 //if(((struct process_with_state *) item->data_val)->state.time_begin.tv_nsec == 987799696)
1503 // printf("HERE!!!\n");
1504 //print_time(((struct process_with_state *) item->data_val)->state.time_begin);
1506 //printf("stack before:\n");
1507 //print_stack(pinfo->stack);
1509 if(item
->data_type
== SSTACK_TYPE_PUSH
) {
1510 struct process_with_state
*pwstate
= item
->data_val
;
1511 //printf("pushing\n");
1512 old_process_push_llev_state(pinfo
, &pwstate
->state
);
1513 update_hlev_state(pinfo
, pwstate
->state
.time_begin
);
1515 else if(item
->data_type
== SSTACK_TYPE_POP
) {
1516 struct process_with_state
*pwstate
= item
->data_val
;
1517 //printf("popping\n");
1518 old_process_pop_llev_state(pinfo
, &pwstate
->state
);
1519 update_hlev_state(pinfo
, pwstate
->state
.time_end
);
1521 else if(item
->data_type
== SSTACK_TYPE_EVENT
) {
1522 struct sstack_event
*se
= item
->data_val
;
1523 if(se
->event_type
== HLEV_EVENT_TRY_WAKEUP
) {
1524 /* FIXME: should change hlev event from BLOCKED to INTERRUPTED CPU when receiving TRY_WAKEUP */
1525 struct try_wakeup_event
*twe
= se
->private;
1527 /* FIXME: maybe do some more rigorous checking here */
1528 if(pinfo
->hlev_state
->bstate
== HLEV_BLOCKED
) {
1529 struct hlev_state_info_blocked
*hlev_blocked_private
= pinfo
->hlev_state
->private;
1531 hlev_blocked_private
->pid_exit
= twe
->pid
;
1532 hlev_blocked_private
->time_woken
= twe
->time
;
1533 hlev_blocked_private
->llev_state_exit
= oldstyle_stack_to_garray(twe
->waker
->llev_state_stack
, twe
->waker
->stack_current
);
1534 //printf("set a non null exit stack on %p, and stack size is %d\n", hlev_blocked_private, hlev_blocked_private->llev_state_exit->len);
1537 if(p->stack_current >= 0 && p->llev_state_stack[p->stack_current]->bstate == LLEV_PREEMPTED) {
1538 old_process_pop_llev_state(pinfo, p->llev_state_stack[p->stack_current]);
1539 update_hlev_state(pinfo
1540 old_process_push_llev_state
1547 //printf("stack after:\n");
1548 //print_stack(pinfo->stack);
1551 static struct process
*get_or_init_process_info(struct LttEvent
*e
, GQuark name
, int pid
, int *new)
1555 val
= g_hash_table_lookup(process_hash_table
, &pid
);
1557 struct process
*pinfo
;
1560 /* Initialize new pinfo for newly discovered process */
1561 pinfo
= g_malloc(sizeof(struct process
));
1563 pinfo
->parent
= -1; /* unknown parent */
1564 pinfo
->hlev_history
= g_array_new(FALSE
, FALSE
, sizeof(struct process_state
*));
1565 pinfo
->stack
= sstack_new();
1566 pinfo
->stack_current
=-1;
1567 pinfo
->stack
->process_func
= process_delayed_stack_action
;
1568 pinfo
->stack
->process_func_arg
= pinfo
;
1569 for(i
=0; i
<PROCESS_STATE_STACK_SIZE
; i
++) {
1570 pinfo
->llev_state_stack
[i
] = g_malloc(sizeof(struct process_state
));
1573 pinfo
->hlev_state
= g_malloc(sizeof(struct process_state
));
1574 pinfo
->hlev_state
->bstate
= HLEV_UNKNOWN
;
1575 pinfo
->hlev_state
->time_begin
= e
->event_time
;
1576 pinfo
->hlev_state
->private = NULL
;
1581 g_hash_table_insert(process_hash_table
, &pinfo
->pid
, pinfo
);
1594 static int differentiate_swappers(int pid
, LttEvent
*e
)
1597 return pid
+e
->tracefile
->cpu_num
+2000000;
1602 static int process_event(void *hook_data
, void *call_data
)
1604 LttvTracefileContext
*tfc
= (LttvTracefileContext
*)call_data
;
1605 LttvTracefileState
*tfs
= (LttvTracefileState
*)call_data
;
1607 struct marker_info
*info
;
1609 /* Extract data from event structures and state */
1610 guint cpu
= tfs
->cpu
;
1611 LttvTraceState
*ts
= (LttvTraceState
*)tfc
->t_context
;
1612 LttvProcessState
*process
= ts
->running_process
[cpu
];
1613 LttTrace
*trace
= ts
->parent
.t
;
1614 struct process
*pinfo
;
1616 e
= ltt_tracefile_get_event(tfs
->parent
.tf
);
1618 info
= marker_get_info_from_id(tfc
->tf
->mdata
, e
->event_id
);
1620 //if(depanalysis_use_time && (ltt_time_compare(e->timestamp, arg_t1) == -1 || ltt_time_compare(e->timestamp, arg_t2) == 1)) {
1623 /* Set the pid for the dependency analysis at each event, until we are passed the range. */
1624 if(depanalysis_use_time
== 3) {
1625 if(ltt_time_compare(e
->event_time
, depanalysis_time2
) <= 0) {
1626 depanalysis_range_pid
= process
->pid
;
1629 /* Should stop processing and print results */
1633 /* Code to limit the event count */
1634 if(depanalysis_event_limit
> 0) {
1635 depanalysis_event_limit
--;
1637 else if(depanalysis_event_limit
== 0) {
1638 write_traceset_footer(hook_data
, call_data
);
1639 printf("exit due to event limit reached\n");
1643 /* write event like textDump for now, for debugging purposes */
1644 //write_event_content(hook_data, call_data);
1646 if(tfc
->tf
->name
== LTT_CHANNEL_SYSCALL_STATE
&& info
->name
== LTT_EVENT_SYS_CALL_TABLE
) {
1648 int *pint
= g_malloc(sizeof(int));
1650 *pint
= field_get_value_int(e
, info
, LTT_FIELD_ID
);
1651 q
= g_quark_from_string(field_get_value_string(e
, info
, LTT_FIELD_SYMBOL
));
1652 g_hash_table_insert(syscall_table
, pint
, q
);
1654 else if(tfc
->tf
->name
== LTT_CHANNEL_IRQ_STATE
&& info
->name
== LTT_EVENT_LIST_INTERRUPT
) {
1656 int *pint
= g_malloc(sizeof(int));
1658 *pint
= field_get_value_int(e
, info
, LTT_FIELD_IRQ_ID
);
1659 q
= g_quark_from_string(field_get_value_string(e
, info
, LTT_FIELD_ACTION
));
1660 g_hash_table_insert(irq_table
, pint
, q
);
1662 else if(tfc
->tf
->name
== LTT_CHANNEL_SOFTIRQ_STATE
&& info
->name
== LTT_EVENT_SOFTIRQ_VEC
) {
1664 int *pint
= g_malloc(sizeof(int));
1666 *pint
= field_get_value_int(e
, info
, LTT_FIELD_ID
);
1667 q
= g_quark_from_string(field_get_value_string(e
, info
, LTT_FIELD_SYMBOL
));
1668 g_hash_table_insert(softirq_table
, pint
, q
);
1672 /* Only look at events after the statedump is finished.
1673 * Before that, the pids in the LttvProcessState are not reliable
1675 if(statedump_finished
== 0) {
1676 if(tfc
->tf
->name
== LTT_CHANNEL_GLOBAL_STATE
&& info
->name
== LTT_EVENT_STATEDUMP_END
)
1677 statedump_finished
= 1;
1683 pinfo
= get_or_init_process_info(e
, process
->name
, differentiate_swappers(process
->pid
, e
), NULL
);
1685 /* the state machine
1686 * Process the event in the context of each process
1689 if(tfc
->tf
->name
== LTT_CHANNEL_KERNEL
&& info
->name
== LTT_EVENT_IRQ_ENTRY
) {
1690 struct process
*event_process_info
= pinfo
;
1691 struct sstack_item
*item
;
1693 item
= prepare_push_item(event_process_info
, LLEV_IRQ
, e
->event_time
);
1694 ((struct llev_state_info_irq
*) item_private(item
))->irq
= field_get_value_int(e
, info
, LTT_FIELD_IRQ_ID
);
1695 commit_item(event_process_info
, item
);
1697 else if(tfc
->tf
->name
== LTT_CHANNEL_KERNEL
&& info
->name
== LTT_EVENT_IRQ_EXIT
) {
1698 struct process
*event_process_info
= pinfo
;
1700 prepare_pop_item_commit(event_process_info
, LLEV_IRQ
, e
->event_time
);
1702 else if(tfc
->tf
->name
== LTT_CHANNEL_KERNEL
&& info
->name
== LTT_EVENT_SCHED_SCHEDULE
) {
1703 int next_pid
= field_get_value_int(e
, info
, LTT_FIELD_NEXT_PID
);
1704 int prev_pid
= field_get_value_int(e
, info
, LTT_FIELD_PREV_PID
);
1706 struct process
*event_process_info
= get_or_init_process_info(e
, process
->name
, differentiate_swappers(next_pid
, e
), NULL
);
1707 prepare_pop_item_commit(event_process_info
, LLEV_PREEMPTED
, e
->event_time
);
1710 struct sstack_item
*item
;
1711 struct process
*event_process_info
= get_or_init_process_info(e
, process
->name
, differentiate_swappers(prev_pid
, e
), NULL
);
1713 item
= prepare_push_item(event_process_info
, LLEV_PREEMPTED
, e
->event_time
);
1714 ((struct llev_state_info_preempted
*) item_private(item
))->prev_state
= field_get_value_int(e
, info
, LTT_FIELD_PREV_STATE
);
1715 commit_item(event_process_info
, item
);
1718 else if(tfc
->tf
->name
== LTT_CHANNEL_KERNEL
&& info
->name
== LTT_EVENT_TRAP_ENTRY
) {
1719 struct process
*event_process_info
= pinfo
;
1720 struct sstack_item
*item
;
1722 item
= prepare_push_item(event_process_info
, LLEV_TRAP
, e
->event_time
);
1723 commit_item(event_process_info
, item
);
1725 else if(tfc
->tf
->name
== LTT_CHANNEL_KERNEL
&& info
->name
== LTT_EVENT_TRAP_EXIT
) {
1726 struct process
*event_process_info
= pinfo
;
1728 prepare_pop_item_commit(event_process_info
, LLEV_TRAP
, e
->event_time
);
1730 else if(tfc
->tf
->name
== LTT_CHANNEL_KERNEL
&& info
->name
== LTT_EVENT_SYSCALL_ENTRY
) {
1731 struct process
*event_process_info
= pinfo
;
1732 struct sstack_item
*item
;
1734 item
= prepare_push_item(event_process_info
, LLEV_SYSCALL
, e
->event_time
);
1735 ((struct llev_state_info_syscall
*) item_private(item
))->syscall_id
= field_get_value_int(e
, info
, LTT_FIELD_SYSCALL_ID
);
1736 ((struct llev_state_info_syscall
*) item_private(item
))->substate
= LLEV_SYSCALL__UNDEFINED
;
1737 commit_item(event_process_info
, item
);
1739 else if(tfc
->tf
->name
== LTT_CHANNEL_KERNEL
&& info
->name
== LTT_EVENT_SYSCALL_EXIT
) {
1740 struct process
*event_process_info
= pinfo
;
1742 prepare_pop_item_commit(event_process_info
, LLEV_SYSCALL
, e
->event_time
);
1744 else if(tfc
->tf
->name
== LTT_CHANNEL_KERNEL
&& info
->name
== LTT_EVENT_SOFT_IRQ_ENTRY
) {
1745 struct process
*event_process_info
= pinfo
;
1746 struct sstack_item
*item
;
1748 item
= prepare_push_item(event_process_info
, LLEV_SOFTIRQ
, e
->event_time
);
1749 ((struct llev_state_info_softirq
*) item_private(item
))->softirq
= field_get_value_int(e
, info
, LTT_FIELD_SOFT_IRQ_ID
);
1750 commit_item(event_process_info
, item
);
1752 else if(tfc
->tf
->name
== LTT_CHANNEL_KERNEL
&& info
->name
== LTT_EVENT_SOFT_IRQ_EXIT
) {
1753 struct process
*event_process_info
= pinfo
;
1755 prepare_pop_item_commit(event_process_info
, LLEV_SOFTIRQ
, e
->event_time
);
1757 else if(tfc
->tf
->name
== LTT_CHANNEL_KERNEL
&& info
->name
== LTT_EVENT_PROCESS_FORK
) {
1758 int pid
= differentiate_swappers(field_get_value_int(e
, info
, LTT_FIELD_CHILD_PID
), e
);
1759 struct process
*event_process_info
= get_or_init_process_info(e
, process
->name
, differentiate_swappers(field_get_value_int(e
, info
, LTT_FIELD_CHILD_PID
), e
), NULL
);
1760 struct sstack_item
*item
;
1762 event_process_info
->parent
= process
->pid
;
1764 //print_time(e->event_time);
1765 //printf(", fork in process %d (%s), creating child %d\n", differentiate_swappers(process->pid, e), g_quark_to_string(process->name), pid);
1767 item
= prepare_push_item(event_process_info
, LLEV_RUNNING
, e
->event_time
);
1768 commit_item(event_process_info
, item
);
1769 item
= prepare_push_item(event_process_info
, LLEV_SYSCALL
, e
->event_time
);
1770 /* FIXME: this sets fork() as syscall, it's pretty inelegant */
1771 ((struct llev_state_info_syscall
*) item_private(item
))->syscall_id
= 57;
1772 ((struct llev_state_info_syscall
*) item_private(item
))->substate
= LLEV_SYSCALL__UNDEFINED
;
1773 commit_item(event_process_info
, item
);
1775 item
= prepare_push_item(event_process_info
, LLEV_PREEMPTED
, e
->event_time
);
1776 /* Consider fork as BLOCKED */
1777 ((struct llev_state_info_preempted
*) item_private(item
))->prev_state
= 1;
1778 commit_item(event_process_info
, item
);
1780 //printf("process %d now has a stack of height %d\n", differentiate_swappers(process->pid, e), get_or_init_process_info(e, process->name, differentiate_swappers(process->pid, cpu), NULL)->stack_current-1);
1783 else if(tfc
->tf
->name
== LTT_CHANNEL_FS
&& info
->name
== LTT_EVENT_EXEC
) {
1784 struct process
*event_process_info
= pinfo
;
1786 guint cpu
= tfs
->cpu
;
1787 LttvProcessState
*process_state
= ts
->running_process
[cpu
];
1788 event_process_info
->name
= process_state
->name
;
1790 else if(tfc
->tf
->name
== LTT_CHANNEL_FS
&& info
->name
== LTT_EVENT_OPEN
) {
1791 struct process_state
*pstate
= process_find_state(pinfo
, LLEV_SYSCALL
);
1792 struct llev_state_info_syscall
*llev_syscall_private
;
1793 struct llev_state_info_syscall__open
*llev_syscall_open_private
;
1795 /* TODO: this is too easy */
1799 llev_syscall_private
= (struct llev_state_info_syscall
*)pstate
->private;
1801 //printf("depanalysis: found an open with state %d in pid %d\n", pstate->bstate, process->pid);
1802 if(pstate
->bstate
== LLEV_UNKNOWN
)
1805 g_assert(pstate
->bstate
== LLEV_SYSCALL
);
1806 g_assert(llev_syscall_private
->substate
== LLEV_SYSCALL__UNDEFINED
);
1808 llev_syscall_private
->substate
= LLEV_SYSCALL__OPEN
;
1809 //printf("setting substate LLEV_SYSCALL__OPEN on syscall_private %p\n", llev_syscall_private);
1810 llev_syscall_private
->private = g_malloc(sizeof(struct llev_state_info_syscall__open
));
1811 llev_syscall_open_private
= llev_syscall_private
->private;
1813 llev_syscall_open_private
->filename
= g_quark_from_string(field_get_value_string(e
, info
, LTT_FIELD_FILENAME
));
1816 else if(tfc
->tf
->name
== LTT_CHANNEL_FS
&& info
->name
== LTT_EVENT_READ
) {
1817 struct process_state
*pstate
= process_find_state(pinfo
, LLEV_SYSCALL
);
1818 struct llev_state_info_syscall
*llev_syscall_private
;
1819 struct llev_state_info_syscall__read
*llev_syscall_read_private
;
1823 /* TODO: this is too easy */
1827 llev_syscall_private
= (struct llev_state_info_syscall
*)pstate
->private;
1829 //printf("depanalysis: found an read with state %d in pid %d\n", pstate->bstate, process->pid);
1830 if(pstate
->bstate
== LLEV_UNKNOWN
)
1833 g_assert(pstate
->bstate
== LLEV_SYSCALL
);
1834 g_assert(llev_syscall_private
->substate
== LLEV_SYSCALL__UNDEFINED
);
1836 llev_syscall_private
->substate
= LLEV_SYSCALL__READ
;
1837 //printf("setting substate LLEV_SYSCALL__READ on syscall_private %p\n", llev_syscall_private);
1838 llev_syscall_private
->private = g_malloc(sizeof(struct llev_state_info_syscall__read
));
1839 llev_syscall_read_private
= llev_syscall_private
->private;
1841 fd
= field_get_value_int(e
, info
, LTT_FIELD_FD
);
1842 pfileq
= g_hash_table_lookup(process
->fds
, fd
);
1844 llev_syscall_read_private
->filename
= pfileq
;
1848 asprintf(&tmp
, "Unknown filename, fd %d", fd
);
1849 llev_syscall_read_private
->filename
= g_quark_from_string(tmp
);
1853 else if(tfc
->tf
->name
== LTT_CHANNEL_FS
&& info
->name
== LTT_EVENT_POLL_EVENT
) {
1854 struct process_state
*pstate
= process_find_state(pinfo
, LLEV_SYSCALL
);
1855 struct llev_state_info_syscall
*llev_syscall_private
;
1856 struct llev_state_info_syscall__poll
*llev_syscall_poll_private
;
1860 /* TODO: this is too easy */
1864 llev_syscall_private
= (struct llev_state_info_syscall
*)pstate
->private;
1866 //printf("depanalysis: found an poll with state %d in pid %d\n", pstate->bstate, process->pid);
1867 if(pstate
->bstate
== LLEV_UNKNOWN
)
1870 /* poll doesn't have a single event that gives the syscall args. instead, there can be an arbitrary
1871 * number of fs_pollfd or fd_poll_event events
1872 * We use the fd_poll_event event, which occurs for each fd that had activity causing a return of the poll()
1873 * For now we only use the first.
1874 * We should do something about this. FIXME
1876 if(llev_syscall_private
->substate
== LLEV_SYSCALL__POLL
)
1879 g_assert(pstate
->bstate
== LLEV_SYSCALL
);
1880 g_assert(llev_syscall_private
->substate
== LLEV_SYSCALL__UNDEFINED
);
1882 llev_syscall_private
->substate
= LLEV_SYSCALL__POLL
;
1883 //printf("setting substate LLEV_SYSCALL__POLL on syscall_private %p\n", llev_syscall_private);
1884 llev_syscall_private
->private = g_malloc(sizeof(struct llev_state_info_syscall__poll
));
1885 llev_syscall_poll_private
= llev_syscall_private
->private;
1887 fd
= field_get_value_int(e
, info
, LTT_FIELD_FD
);
1888 pfileq
= g_hash_table_lookup(process
->fds
, fd
);
1890 llev_syscall_poll_private
->filename
= pfileq
;
1894 asprintf(&tmp
, "Unknown filename, fd %d", fd
);
1895 llev_syscall_poll_private
->filename
= g_quark_from_string(tmp
);
1899 else if(tfc
->tf
->name
== LTT_CHANNEL_KERNEL
&& info
->name
== LTT_EVENT_SCHED_TRY_WAKEUP
) {
1900 struct sstack_event
*se
= g_malloc(sizeof(struct sstack_event
));
1901 struct try_wakeup_event
*twe
= g_malloc(sizeof(struct try_wakeup_event
));
1902 struct sstack_item
*item
= sstack_item_new_event();
1903 int target
= field_get_value_int(e
, info
, LTT_FIELD_PID
);
1904 struct process
*target_pinfo
;
1907 se
->event_type
= HLEV_EVENT_TRY_WAKEUP
;
1909 //printf("pushing try wake up event in context of %d\n", pinfo->pid);
1911 twe
->pid
= differentiate_swappers(process
->pid
, e
);
1912 twe
->time
= e
->event_time
;
1915 /* FIXME: the target could not yet have an entry in the hash table, we would then lose data */
1916 target_pinfo
= g_hash_table_lookup(process_hash_table
, &target
);
1920 item
->data_val
= se
;
1921 item
->delete_data_val
= (void (*)(void *))delete_data_val
;
1923 sstack_add_item(target_pinfo
->stack
, item
);
1925 /* Now pop the blocked schedule out of the target */
1926 result
= try_pop_blocked_llev_preempted(target_pinfo
, e
->event_time
);
1929 struct sstack_item
*item
;
1930 struct process
*event_process_info
= target_pinfo
;
1932 item
= prepare_push_item(event_process_info
, LLEV_PREEMPTED
, e
->event_time
);
1933 ((struct llev_state_info_preempted
*) item_private(item
))->prev_state
= -1; /* special value meaning post-block sched out */
1934 commit_item(event_process_info
, item
);
1944 void print_sstack_private(struct sstack_item
*item
)
1946 struct process_with_state
*pwstate
= item
->data_val
;
1948 if(pwstate
&& item
->data_type
== SSTACK_TYPE_PUSH
)
1949 printf("\tstate: %s", llev_state_infos
[pwstate
->state
.bstate
].name
);
1952 print_time(pwstate
->state
.time_begin
);
1954 print_time(pwstate
->state
.time_end
);
1959 static LttTime
ltt_time_from_string(const char *str
)
1963 char *decdot
= strchr(str
, '.');
1967 retval
.tv_nsec
= atol(decdot
+1);
1973 retval
.tv_sec
= atol(str
);
1978 static void arg_t1(void *hook_data
)
1981 depanalysis_use_time
|= 1;
1982 depanalysis_time1
= ltt_time_from_string(arg_t1_str
);
1985 static void arg_t2(void *hook_data
)
1987 depanalysis_use_time
|= 2;
1988 depanalysis_time2
= ltt_time_from_string(arg_t2_str
);
1991 static void arg_pid(void *hook_data
)
1995 static void arg_limit(void *hook_data
)
1999 static void arg_sum(void *hook_data
)
2007 print_sstack_item_data
= print_sstack_private
;
2009 LttvAttributeValue value
;
2011 LttvIAttribute
*attributes
= LTTV_IATTRIBUTE(lttv_global_attributes());
2015 lttv_option_add("dep-time-start", 0, "dependency analysis time of analysis start", "time",
2016 LTTV_OPT_STRING
, &arg_t1_str
, arg_t1
, NULL
);
2017 lttv_option_add("dep-time-end", 0, "dependency analysis time of analysis end", "time",
2018 LTTV_OPT_STRING
, &arg_t2_str
, arg_t2
, NULL
);
2019 lttv_option_add("dep-pid", 0, "dependency analysis pid", "pid",
2020 LTTV_OPT_INT
, &depanalysis_range_pid_searching
, arg_pid
, NULL
);
2021 lttv_option_add("limit-events", 0, "dependency limit event count", "count",
2022 LTTV_OPT_INT
, &depanalysis_event_limit
, arg_limit
, NULL
);
2023 lttv_option_add("print-summary", 0, "print simple summary", "sum",
2024 LTTV_OPT_INT
, &a_print_simple_summary
, arg_sum
, NULL
);
2026 process_hash_table
= g_hash_table_new(g_int_hash
, g_int_equal
);
2027 syscall_table
= g_hash_table_new(g_int_hash
, g_int_equal
);
2028 irq_table
= g_hash_table_new(g_int_hash
, g_int_equal
);
2029 softirq_table
= g_hash_table_new(g_int_hash
, g_int_equal
);
2031 a_string
= g_string_new("");
2033 result
= lttv_iattribute_find_by_path(attributes
, "hooks/event",
2034 LTTV_POINTER
, &value
);
2036 event_hook
= *(value
.v_pointer
);
2037 g_assert(event_hook
);
2038 lttv_hooks_add(event_hook
, process_event
, NULL
, LTTV_PRIO_DEFAULT
);
2040 // result = lttv_iattribute_find_by_path(attributes, "hooks/trace/before",
2041 // LTTV_POINTER, &value);
2042 // g_assert(result);
2043 // before_trace = *(value.v_pointer);
2044 // g_assert(before_trace);
2045 // lttv_hooks_add(before_trace, write_trace_header, NULL, LTTV_PRIO_DEFAULT);
2047 result
= lttv_iattribute_find_by_path(attributes
, "hooks/traceset/before",
2048 LTTV_POINTER
, &value
);
2050 before_traceset
= *(value
.v_pointer
);
2051 g_assert(before_traceset
);
2052 lttv_hooks_add(before_traceset
, write_traceset_header
, NULL
,
2055 result
= lttv_iattribute_find_by_path(attributes
, "hooks/traceset/after",
2056 LTTV_POINTER
, &value
);
2058 after_traceset
= *(value
.v_pointer
);
2059 g_assert(after_traceset
);
2060 lttv_hooks_add(after_traceset
, write_traceset_footer
, NULL
,
2064 static void destroy()
2066 lttv_option_remove("dep-time-start");
2067 lttv_option_remove("dep-time-end");
2068 lttv_option_remove("dep-pid");
2069 lttv_option_remove("limit-events");
2070 lttv_option_remove("print-summary");
2072 g_hash_table_destroy(process_hash_table
);
2073 g_hash_table_destroy(syscall_table
);
2074 g_hash_table_destroy(irq_table
);
2075 g_hash_table_destroy(softirq_table
);
2077 g_string_free(a_string
, TRUE
);
2079 lttv_hooks_remove_data(event_hook
, write_event_content
, NULL
);
2080 // lttv_hooks_remove_data(before_trace, write_trace_header, NULL);
2081 lttv_hooks_remove_data(before_traceset
, write_traceset_header
, NULL
);
2082 lttv_hooks_remove_data(after_traceset
, write_traceset_footer
, NULL
);
2085 LTTV_MODULE("depanalysis", "Dependency analysis test", \
2086 "Produce a dependency analysis of a trace", \
2087 init
, destroy
, "stats", "batchAnalysis", "option", "print")