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