1235368Sgnn#!/usr/sbin/dtrace -s
2235368Sgnn/*
3235368Sgnn * weblatency.d - website latency statistics.
4235368Sgnn *		  Written using DTrace (Solaris 10 3/05).
5235368Sgnn *
6235368Sgnn * $Id: weblatency.d 3 2007-08-01 10:50:08Z brendan $
7235368Sgnn *
8235368Sgnn * USAGE:	weblatency.d 	# hit Ctrl-C to end sample
9235368Sgnn *
10235368Sgnn * See the code below for the "BROWSER" variable, which sets the browser
11235368Sgnn * to trace (currently set to "mozilla-bin").
12235368Sgnn *
13235368Sgnn * This is written as an experimental tool, and may not work at all with
14235368Sgnn * your browser.
15235368Sgnn *
16235368Sgnn * FIELDS:
17235368Sgnn *		HOST		Hostname from URL
18235368Sgnn *		NUM		Number of GETs
19235368Sgnn *		AVGTIME(ms)	Average time for response, ms
20235368Sgnn *		MAXTIME(ms)	Maximum time for response, ms
21235368Sgnn *
22235368Sgnn * NOTE:
23235368Sgnn *
24235368Sgnn * The latency measured here is from the browser sending the GET
25235368Sgnn * request to when the browser begins to recieve the response. It
26235368Sgnn * is an overall response time for the client, and encompasses
27235368Sgnn * connection speed delays, DNS lookups, proxy delays, and web server
28235368Sgnn * response time.
29235368Sgnn *
30235368Sgnn * IDEA: Bryan Cantrill (who wrote an elegant version for Sol 10 update 1)
31235368Sgnn *
32235368Sgnn * COPYRIGHT: Copyright (c) 2005, 2006 Brendan Gregg.
33235368Sgnn *
34235368Sgnn * CDDL HEADER START
35235368Sgnn *
36235368Sgnn *  The contents of this file are subject to the terms of the
37235368Sgnn *  Common Development and Distribution License, Version 1.0 only
38235368Sgnn *  (the "License").  You may not use this file except in compliance
39235368Sgnn *  with the License.
40235368Sgnn *
41235368Sgnn *  You can obtain a copy of the license at Docs/cddl1.txt
42235368Sgnn *  or http://www.opensolaris.org/os/licensing.
43235368Sgnn *  See the License for the specific language governing permissions
44235368Sgnn *  and limitations under the License.
45235368Sgnn *
46235368Sgnn * CDDL HEADER END
47235368Sgnn *
48235368Sgnn * ToDo:
49235368Sgnn *	Check write fd for socket, not file.
50235368Sgnn *
51235368Sgnn * 30-Nov-2005  Brendan Gregg   Created this.
52235368Sgnn * 20-Apr-2006	   "	  "	Last update.
53235368Sgnn */
54235368Sgnn
55235368Sgnn#pragma D option quiet
56235368Sgnn
57235368Sgnn/* browser's execname */
58235368Sgnninline string BROWSER = "mozilla-bin";
59235368Sgnn
60235368Sgnn/* maximum expected hostname length + "GET http://" */
61235368Sgnninline int MAX_REQ = 64;
62235368Sgnn
63235368Sgnndtrace:::BEGIN
64235368Sgnn{
65235368Sgnn	printf("Tracing... Hit Ctrl-C to end.\n");
66235368Sgnn}
67235368Sgnn
68235368Sgnn/*
69235368Sgnn * Trace brower request
70235368Sgnn *
71235368Sgnn * This is achieved by matching writes for the browser's execname that
72235368Sgnn * start with "GET", and then timing from the return of the write to
73235368Sgnn * the return of the next read in the same thread. Various stateful flags
74235368Sgnn * are used: self->fd, self->read.
75235368Sgnn *
76235368Sgnn * For performance reasons, I'd like to only process writes that follow a
77235368Sgnn * connect(), however this approach fails to process keepalives.
78235368Sgnn */
79235368Sgnnsyscall::write:entry
80235368Sgnn/execname == BROWSER/
81235368Sgnn{
82235368Sgnn	self->buf = arg1;
83235368Sgnn	self->fd = arg0 + 1;
84235368Sgnn	self->nam = "";
85235368Sgnn}
86235368Sgnn
87235368Sgnnsyscall::write:return
88235368Sgnn/self->fd/
89235368Sgnn{
90235368Sgnn	this->str = (char *)copyin(self->buf, MAX_REQ);
91235368Sgnn	this->str[4] = '\0';
92235368Sgnn	self->fd = stringof(this->str) == "GET " ? self->fd : 0;
93235368Sgnn}
94235368Sgnn
95235368Sgnnsyscall::write:return
96235368Sgnn/self->fd/
97235368Sgnn{
98235368Sgnn	/* fetch browser request */
99235368Sgnn	this->str = (char *)copyin(self->buf, MAX_REQ);
100235368Sgnn	this->str[MAX_REQ] = '\0';
101235368Sgnn
102235368Sgnn	/*
103235368Sgnn	 * This unrolled loop strips down a URL to it's hostname.
104235368Sgnn	 * We ought to use strtok(), but it's not available on Sol 10 3/05,
105235368Sgnn	 * so instead I used dirname(). It's not pretty - it's done so that
106235368Sgnn	 * this works on all Sol 10 versions.
107235368Sgnn	 */
108235368Sgnn	self->req = stringof(this->str);
109235368Sgnn	self->nam = strlen(self->req) > 15 ? self->req : self->nam;
110235368Sgnn	self->req = dirname(self->req);
111235368Sgnn	self->nam = strlen(self->req) > 15 ? self->req : self->nam;
112235368Sgnn	self->req = dirname(self->req);
113235368Sgnn	self->nam = strlen(self->req) > 15 ? self->req : self->nam;
114235368Sgnn	self->req = dirname(self->req);
115235368Sgnn	self->nam = strlen(self->req) > 15 ? self->req : self->nam;
116235368Sgnn	self->req = dirname(self->req);
117235368Sgnn	self->nam = strlen(self->req) > 15 ? self->req : self->nam;
118235368Sgnn	self->req = dirname(self->req);
119235368Sgnn	self->nam = strlen(self->req) > 15 ? self->req : self->nam;
120235368Sgnn	self->req = dirname(self->req);
121235368Sgnn	self->nam = strlen(self->req) > 15 ? self->req : self->nam;
122235368Sgnn	self->req = dirname(self->req);
123235368Sgnn	self->nam = strlen(self->req) > 15 ? self->req : self->nam;
124235368Sgnn	self->req = dirname(self->req);
125235368Sgnn	self->nam = strlen(self->req) > 15 ? self->req : self->nam;
126235368Sgnn	self->nam = basename(self->nam);
127235368Sgnn
128235368Sgnn	/* start the timer */
129235368Sgnn	start[pid, self->fd - 1] = timestamp;
130235368Sgnn	host[pid, self->fd - 1] = self->nam;
131235368Sgnn	self->buf = 0;
132235368Sgnn	self->fd  = 0;
133235368Sgnn	self->req = 0;
134235368Sgnn	self->nam = 0;
135235368Sgnn}
136235368Sgnn
137235368Sgnn/* this one wasn't a GET */
138235368Sgnnsyscall::write:return
139235368Sgnn/self->buf/
140235368Sgnn{
141235368Sgnn	self->buf = 0;
142235368Sgnn	self->fd  = 0;
143235368Sgnn}
144235368Sgnn
145235368Sgnnsyscall::read:entry
146235368Sgnn/execname == BROWSER && start[pid, arg0]/
147235368Sgnn{
148235368Sgnn	self->fd = arg0 + 1;
149235368Sgnn}
150235368Sgnn
151235368Sgnn/*
152235368Sgnn * Record host details
153235368Sgnn */
154235368Sgnnsyscall::read:return
155235368Sgnn/self->fd/
156235368Sgnn{
157235368Sgnn	/* fetch details */
158235368Sgnn	self->host = stringof(host[pid, self->fd - 1]);
159235368Sgnn	this->start = start[pid, self->fd - 1];
160235368Sgnn
161235368Sgnn	/* save details */
162235368Sgnn	@Avg[self->host] = avg((timestamp - this->start)/1000000);
163235368Sgnn	@Max[self->host] = max((timestamp - this->start)/1000000);
164235368Sgnn	@Num[self->host] = count();
165235368Sgnn
166235368Sgnn	/* clear vars */
167235368Sgnn	start[pid, self->fd - 1] = 0;
168235368Sgnn	host[pid, self->fd - 1] = 0;
169235368Sgnn	self->host = 0;
170235368Sgnn	self->fd = 0;
171235368Sgnn}
172235368Sgnn
173235368Sgnn/*
174235368Sgnn * Output report
175235368Sgnn */
176235368Sgnndtrace:::END
177235368Sgnn{
178235368Sgnn	printf("%-32s %11s\n", "HOST", "NUM");
179235368Sgnn	printa("%-32s %@11d\n", @Num);
180235368Sgnn
181235368Sgnn	printf("\n%-32s %11s\n", "HOST", "AVGTIME(ms)");
182235368Sgnn	printa("%-32s %@11d\n", @Avg);
183235368Sgnn
184235368Sgnn	printf("\n%-32s %11s\n", "HOST", "MAXTIME(ms)");
185235368Sgnn	printa("%-32s %@11d\n", @Max);
186235368Sgnn}
187