1#!/usr/sbin/dtrace -Zs
2/*
3 * tcl_flowtime.d - snoop Tcl execution showing procedure flow and delta times.
4 *                  Written for the Tcl DTrace provider.
5 *
6 * $Id: tcl_flowtime.d 63 2007-10-04 04:34:38Z brendan $
7 *
8 * This traces activity from all Tcl processes on the system with DTrace
9 * provider support (tcl8.4.16).
10 *
11 * USAGE: tcl_flowtime.d		# hit Ctrl-C to end
12 *
13 * This watches Tcl method entries and returns, and indents child
14 * method calls.
15 *
16 * FIELDS:
17 *		C		CPU-id
18 *		PID		Process ID
19 *		TIME(us)	Time since boot, us
20 *		DELTA(us)	Elapsed time from previous line to this line
21 *		CALL		Tcl command or procedure name
22 *
23 * LEGEND:
24 *		->		procedure entry
25 *		<-		procedure return
26 *		 >		command entry
27 *		 <		command return
28 *
29 * WARNING: Watch the first column carefully, it prints the CPU-id. If it
30 * changes, then it is very likely that the output has been shuffled.
31 *
32 * COPYRIGHT: Copyright (c) 2007 Brendan Gregg.
33 *
34 * CDDL HEADER START
35 *
36 *  The contents of this file are subject to the terms of the
37 *  Common Development and Distribution License, Version 1.0 only
38 *  (the "License").  You may not use this file except in compliance
39 *  with the License.
40 *
41 *  You can obtain a copy of the license at Docs/cddl1.txt
42 *  or http://www.opensolaris.org/os/licensing.
43 *  See the License for the specific language governing permissions
44 *  and limitations under the License.
45 *
46 * CDDL HEADER END
47 *
48 * 09-Sep-2007	Brendan Gregg	Created this.
49 */
50
51#pragma D option quiet
52#pragma D option switchrate=10
53
54self int depth;
55
56dtrace:::BEGIN
57{
58	printf("%3s %6s %-16s %9s -- %s\n", "C", "PID", "TIME(us)",
59	    "DELTA(us)", "CALL");
60}
61
62tcl*:::proc-entry,
63tcl*:::proc-return,
64tcl*:::cmd-entry,
65tcl*:::cmd-return
66/self->last == 0/
67{
68	self->last = timestamp;
69}
70
71tcl*:::proc-entry
72{
73	this->delta = (timestamp - self->last) / 1000;
74	printf("%3d %6d %-16d %9d %*s-> %s\n", cpu, pid, timestamp / 1000,
75	    this->delta, self->depth * 2, "", copyinstr(arg0));
76	self->depth++;
77	self->last = timestamp;
78}
79
80tcl*:::proc-return
81{
82	this->delta = (timestamp - self->last) / 1000;
83	self->depth -= self->depth > 0 ? 1 : 0;
84	printf("%3d %6d %-16d %9d %*s<- %s\n", cpu, pid, timestamp / 1000,
85	    this->delta, self->depth * 2, "", copyinstr(arg0));
86	self->last = timestamp;
87}
88
89tcl*:::cmd-entry
90{
91	this->delta = (timestamp - self->last) / 1000;
92	printf("%3d %6d %-16d %9d %*s > %s\n", cpu, pid, timestamp / 1000,
93	    this->delta, self->depth * 2, "", copyinstr(arg0));
94	self->depth++;
95	self->last = timestamp;
96}
97
98tcl*:::cmd-return
99{
100	this->delta = (timestamp - self->last) / 1000;
101	self->depth -= self->depth > 0 ? 1 : 0;
102	printf("%3d %6d %-16d %9d %*s < %s\n", cpu, pid, timestamp / 1000,
103	    this->delta, self->depth * 2, "", copyinstr(arg0));
104	self->last = timestamp;
105}
106