1#!/usr/sbin/dtrace -s
2/*
3 * weblatency.d - website latency statistics.
4 *		  Written using DTrace (Solaris 10 3/05).
5 *
6 * $Id: weblatency.d 3 2007-08-01 10:50:08Z brendan $
7 *
8 * USAGE:	weblatency.d 	# hit Ctrl-C to end sample
9 *
10 * See the code below for the "BROWSER" variable, which sets the browser
11 * to trace (currently set to "mozilla-bin").
12 *
13 * This is written as an experimental tool, and may not work at all with
14 * your browser.
15 *
16 * FIELDS:
17 *		HOST		Hostname from URL
18 *		NUM		Number of GETs
19 *		AVGTIME(ms)	Average time for response, ms
20 *		MAXTIME(ms)	Maximum time for response, ms
21 *
22 * NOTE:
23 *
24 * The latency measured here is from the browser sending the GET
25 * request to when the browser begins to recieve the response. It
26 * is an overall response time for the client, and encompasses
27 * connection speed delays, DNS lookups, proxy delays, and web server
28 * response time.
29 *
30 * IDEA: Bryan Cantrill (who wrote an elegant version for Sol 10 update 1)
31 *
32 * COPYRIGHT: Copyright (c) 2005, 2006 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 * ToDo:
49 *	Check write fd for socket, not file.
50 *
51 * 30-Nov-2005  Brendan Gregg   Created this.
52 * 20-Apr-2006	   "	  "	Last update.
53 */
54
55#pragma D option quiet
56
57/* browser's execname */
58inline string BROWSER = "mozilla-bin";
59
60/* maximum expected hostname length + "GET http://" */
61inline int MAX_REQ = 64;
62
63dtrace:::BEGIN
64{
65	printf("Tracing... Hit Ctrl-C to end.\n");
66}
67
68/*
69 * Trace brower request
70 *
71 * This is achieved by matching writes for the browser's execname that
72 * start with "GET", and then timing from the return of the write to
73 * the return of the next read in the same thread. Various stateful flags
74 * are used: self->fd, self->read.
75 *
76 * For performance reasons, I'd like to only process writes that follow a
77 * connect(), however this approach fails to process keepalives.
78 */
79syscall::write:entry
80/execname == BROWSER/
81{
82	self->buf = arg1;
83	self->fd = arg0 + 1;
84	self->nam = "";
85}
86
87syscall::write:return
88/self->fd/
89{
90	this->str = (char *)copyin(self->buf, MAX_REQ);
91	this->str[4] = '\0';
92	self->fd = stringof(this->str) == "GET " ? self->fd : 0;
93}
94
95syscall::write:return
96/self->fd/
97{
98	/* fetch browser request */
99	this->str = (char *)copyin(self->buf, MAX_REQ);
100	this->str[MAX_REQ] = '\0';
101
102	/*
103	 * This unrolled loop strips down a URL to it's hostname.
104	 * We ought to use strtok(), but it's not available on Sol 10 3/05,
105	 * so instead I used dirname(). It's not pretty - it's done so that
106	 * this works on all Sol 10 versions.
107	 */
108	self->req = stringof(this->str);
109	self->nam = strlen(self->req) > 15 ? self->req : self->nam;
110	self->req = dirname(self->req);
111	self->nam = strlen(self->req) > 15 ? self->req : self->nam;
112	self->req = dirname(self->req);
113	self->nam = strlen(self->req) > 15 ? self->req : self->nam;
114	self->req = dirname(self->req);
115	self->nam = strlen(self->req) > 15 ? self->req : self->nam;
116	self->req = dirname(self->req);
117	self->nam = strlen(self->req) > 15 ? self->req : self->nam;
118	self->req = dirname(self->req);
119	self->nam = strlen(self->req) > 15 ? self->req : self->nam;
120	self->req = dirname(self->req);
121	self->nam = strlen(self->req) > 15 ? self->req : self->nam;
122	self->req = dirname(self->req);
123	self->nam = strlen(self->req) > 15 ? self->req : self->nam;
124	self->req = dirname(self->req);
125	self->nam = strlen(self->req) > 15 ? self->req : self->nam;
126	self->nam = basename(self->nam);
127
128	/* start the timer */
129	start[pid, self->fd - 1] = timestamp;
130	host[pid, self->fd - 1] = self->nam;
131	self->buf = 0;
132	self->fd  = 0;
133	self->req = 0;
134	self->nam = 0;
135}
136
137/* this one wasn't a GET */
138syscall::write:return
139/self->buf/
140{
141	self->buf = 0;
142	self->fd  = 0;
143}
144
145syscall::read:entry
146/execname == BROWSER && start[pid, arg0]/
147{
148	self->fd = arg0 + 1;
149}
150
151/*
152 * Record host details
153 */
154syscall::read:return
155/self->fd/
156{
157	/* fetch details */
158	self->host = stringof(host[pid, self->fd - 1]);
159	this->start = start[pid, self->fd - 1];
160
161	/* save details */
162	@Avg[self->host] = avg((timestamp - this->start)/1000000);
163	@Max[self->host] = max((timestamp - this->start)/1000000);
164	@Num[self->host] = count();
165
166	/* clear vars */
167	start[pid, self->fd - 1] = 0;
168	host[pid, self->fd - 1] = 0;
169	self->host = 0;
170	self->fd = 0;
171}
172
173/*
174 * Output report
175 */
176dtrace:::END
177{
178	printf("%-32s %11s\n", "HOST", "NUM");
179	printa("%-32s %@11d\n", @Num);
180
181	printf("\n%-32s %11s\n", "HOST", "AVGTIME(ms)");
182	printa("%-32s %@11d\n", @Avg);
183
184	printf("\n%-32s %11s\n", "HOST", "MAXTIME(ms)");
185	printa("%-32s %@11d\n", @Max);
186}
187