Wiki code for JavaScript Tracing

Hide Line numbers
1: = JavaScript Tracing
2: 
3:  The following are example scripts for tracing JavaScript using the [[Mozilla DTrace>>Project mozilla-dtrace.WebHome]] provider.
4: 
5: == Example Scripts
6: 
7: These scripts have been writen to trace activity from all browsers on the system that support the Mozilla DTrace provider; to trace single browser instances, modify the scripts to match the provider "javascript$target" and run the scripts with "-p PID" as the argument.
8: 
9: A feature of DTrace is that the browser does not need to be restarted for DTrace to work. The JavaScript probes cause zero overhead until they are enabled by a DTrace script, and tracing begins.
10: 
11: === Example Target: clock.html
12: 
13:  This simple JavaScript clock will be run as the target for the tracing demonstrations that follow,
14: 
15: {{{
16: 
17: <HTML>
18: <HEAD>
19: <TITLE>Clock, JavaScript</TITLE>
20: <SCRIPT type="text/javascript">
21: function padZero(i)
22: {
23:         if (i < 10) return "0" + i;
24:         return i;
25: }
26: 
27: function startTime()
28: {
29:         var now = new Date;
30:         var time = padZero(now.getHours()) + ":" +
31:             padZero(now.getMinutes()) + ":" +
32:             padZero(now.getSeconds());
33:         document.getElementById(’clock’).innerHTML = "time: " + time + "<br>";
34:         var timeout = setTimeout(’startTime()’, 1000);
35: }
36: </SCRIPT>
37: </HEAD>
38: <BODY onload="startTime()">
39: <DIV id="clock"></DIV>
40: </BODY>
41: </HTML>
42: 
43: }}}
44: 
45: === js_funccalls.d
46: 
47:  This is a simple script to count the number of JavaScript function calls while the script was running.
48: 
49: {{{
50: 
51: #!/usr/sbin/dtrace -Zs
52: /*
53:  * js_funccalls.d - measure JavaScript function calls using DTrace.
54:  *                  Written for the Solaris Mozilla DTrace provider.
55:  *
56:  * This traces JavaScript activity from all running browers on the system
57:  * which support the mozilla DTrace provider.
58:  *
59:  * USAGE: js_calls.d            # hit Ctrl-C to end
60:  *
61:  * FIELDS:
62:  *              FILE            Filename that contained the function
63:  *              FUNC            JavaScript function name
64:  *              CALLS           Function calls during this sample
65:  *
66:  * Filename and function names are printed if available, else "<null>".
67:  */
68: #pragma ident   "@(#)js_funccalls.d     1.3     07/03/26 SMI"
69: 
70: #pragma D option quiet
71: 
72: dtrace:::BEGIN
73: {
74:         printf("Tracing... Hit Ctrl-C to end.\n");
75: }
76: 
77: javascript*:::function-entry
78: {
79:         @funcs[basename(copyinstr(arg0)), copyinstr(arg2)] = count();
80: }
81: 
82: dtrace:::END
83: {
84:         printf(" %-32s %-36s %8s\n", "FILE", "FUNC", "CALLS");
85:         printa(" %-32s %-36s %@8d\n", @funcs);
86: }
87: 
88: }}}
89: 
90:  Example output,
91: 
92: {{{
93: 
94: # ./js_funccalls.d 
95: Tracing... Hit Ctrl-C to end.
96: ^C
97:  FILE                             FUNC                                    CALLS
98:  nsMicrosummaryService.js         GetSources                                  1
99:  nsMicrosummaryService.js         MSS__getBookmarks                           1
100:  nsMicrosummaryService.js         MSS__updateMicrosummaries                   1
101:  nsMicrosummaryService.js         getPref                                     1
102:  nsMicrosummaryService.js         getPrefType                                 1
103:  nsMicrosummaryService.js         getService                                  1
104:  nsMicrosummaryService.js         hasMoreElements                             1
105:  nsMicrosummaryService.js         max                                         1
106:  nsMicrosummaryService.js         now                                         1
107:  nsMicrosummaryService.js         GetResource                                 2
108:  nsMicrosummaryService.js         MSS__resource                               2
109:  clock.html                       getElementById                              3
110:  clock.html                       getHours                                    3
111:  clock.html                       getMinutes                                  3
112:  clock.html                       getSeconds                                  3
113:  clock.html                       setTimeout                                  3
114:  clock.html                       startTime                                   3
115:  clock.html                       padZero                                     9
116: 
117: }}}
118: 
119: Apart from events from clock.html, the script also traced some events from the browser.
120: 
121: === js_funcinfo.d
122: 
123:  This script is similar to js_funccalls.d, however prints additional call information which is especially useful for tracing anonymous functions,
124: 
125: {{{
126: 
127: # ./js_funcinfo.d
128: Tracing... Hit Ctrl-C to end.
129: ^C
130:  BASE[FILE:LINE]         FUNCNAME             RUN[FILE:LINE]             CALLS
131:  clock2.html:7           getElementById       clock2.html:12                 1
132:  clock2.html:7           getHours             clock2.html:9                  1
133:  clock2.html:7           getMinutes           clock2.html:10                 1
134:  clock2.html:7           getSeconds           clock2.html:11                 1
135:  clock2.html:7           setTimeout           clock2.html:13                 1
136:  clock2.html:7           startTime            clock2.html:13                 1
137:  clocklib.js:2           padLibZero           clock2.html:10                 1
138:  clocklib.js:2           padLibZero           clock2.html:11                 1
139:  clocklib.js:2           padLibZero           clock2.html:9                  1
140: 
141: }}}
142: 
143: The "BASE" details show where the function was declared or first used; the "RUN" info shows where the function was executed.
144: 
145: === js_funcflow.d
146: 
147:  This script traces the flow of JavaScript functions, by indenting as a function is entered and un-indenting as the function completes.
148: 
149: {{{
150: 
151: #!/usr/sbin/dtrace -Zs
152: /*
153:  * js_funcflow.d - snoop JavaScript function execution using DTrace.
154:  *                 Written for the Solaris Mozilla DTrace provider.
155:  *
156:  * This traces JavaScript activity from all running browers on the system
157:  * which support the mozilla DTrace provider.
158:  *
159:  * USAGE: js_funcflow.d                 # hit Ctrl-C to end
160:  *
161:  * This watches JavaScript function entries and returns, and indents child
162:  * function calls. For busy JavaScript, the output will be very verbose.
163:  *
164:  * FIELDS:
165:  *              C               CPU-id
166:  *              TIME            Time of function call
167:  *              FILE            Filename that this function belongs to
168:  *              FUNC            JavaScript function name
169:  *
170:  * Filename and function names are printed if available, else "<null>".
171:  *
172:  * WARNING: Watch the first column carefully, it prints the CPU-id. If it
173:  * changes, then it is very likely that the output has been shuffled.
174:  */
175: #pragma ident   "@(#)js_funcflow.d      1.3     07/03/26 SMI"
176: 
177: #pragma D option quiet
178: #pragma D option switchrate=10
179: 
180: dtrace:::BEGIN
181: {
182:         depth = 0;
183:         printf("%s %-20s  %-22s   ~-- %s\n", "C", "TIME", "FILE", "FUNC");
184: }
185: 
186: javascript*:::function-entry
187: {
188:         depth++;
189:         printf("%d %-20Y  %-22s %*s-> %s\n", cpu, walltimestamp, 
190:             basename(copyinstr(arg0)), depth*2, "", copyinstr(arg2));
191: }
192: 
193: javascript*:::function-return
194: {
195:         printf("%d %-20Y  %-22s %*s<- %s\n", cpu, walltimestamp,
196:             basename(copyinstr(arg0)), depth*2, "", copyinstr(arg2));
197:         depth~--;
198: }
199: 
200: }}}
201: 
202: Running this script while clock.html runs produces,
203: 
204: {{{
205: 
206: # ./js_funcflow.d 
207: C TIME                  FILE                     ~-- FUNC
208: 0 2007 Mar 26 16:42:09  clock.html               -> startTime
209: 0 2007 Mar 26 16:42:09  clock.html                 -> getHours
210: 0 2007 Mar 26 16:42:09  clock.html                 <- getHours
211: 0 2007 Mar 26 16:42:09  clock.html                 -> padZero
212: 0 2007 Mar 26 16:42:09  clock.html                 <- padZero
213: 0 2007 Mar 26 16:42:09  clock.html                 -> getMinutes
214: 0 2007 Mar 26 16:42:09  clock.html                 <- getMinutes
215: 0 2007 Mar 26 16:42:09  clock.html                 -> padZero
216: 0 2007 Mar 26 16:42:09  clock.html                 <- padZero
217: 0 2007 Mar 26 16:42:09  clock.html                 -> getSeconds
218: 0 2007 Mar 26 16:42:09  clock.html                 <- getSeconds
219: 0 2007 Mar 26 16:42:09  clock.html                 -> padZero
220: 0 2007 Mar 26 16:42:09  clock.html                 <- padZero
221: 0 2007 Mar 26 16:42:09  clock.html                 -> getElementById
222: 0 2007 Mar 26 16:42:09  clock.html                 <- getElementById
223: 0 2007 Mar 26 16:42:09  clock.html                 -> setTimeout
224: 0 2007 Mar 26 16:42:09  clock.html                 <- setTimeout
225: 0 2007 Mar 26 16:42:09  clock.html               <- startTime
226: 0 2007 Mar 26 16:42:10  clock.html               -> startTime
227: 0 2007 Mar 26 16:42:10  clock.html                 -> getHours
228: 0 2007 Mar 26 16:42:10  clock.html                 <- getHours
229: 0 2007 Mar 26 16:42:10  clock.html                 -> padZero
230: 0 2007 Mar 26 16:42:10  clock.html                 <- padZero
231: 0 2007 Mar 26 16:42:10  clock.html                 -> getMinutes
232: 0 2007 Mar 26 16:42:10  clock.html                 <- getMinutes
233: 0 2007 Mar 26 16:42:10  clock.html                 -> padZero
234: 0 2007 Mar 26 16:42:10  clock.html                 <- padZero
235: 0 2007 Mar 26 16:42:10  clock.html                 -> getSeconds
236: 0 2007 Mar 26 16:42:10  clock.html                 <- getSeconds
237: 0 2007 Mar 26 16:42:10  clock.html                 -> padZero
238: 0 2007 Mar 26 16:42:10  clock.html                 <- padZero
239: 0 2007 Mar 26 16:42:10  clock.html                 -> getElementById
240: 0 2007 Mar 26 16:42:10  clock.html                 <- getElementById
241: 0 2007 Mar 26 16:42:10  clock.html                 -> setTimeout
242: 0 2007 Mar 26 16:42:10  clock.html                 <- setTimeout
243: 0 2007 Mar 26 16:42:10  clock.html               <- startTime
244: ^C
245: 
246: }}}
247: 
248: The execution of the clock.html script can be seen. This tool isn’t as useful as it may appear - serious JavaScript applications will produce hundreds of pages of output per second. Perhaps this is more useful as a demonstration of DTrace capabilities.
249: 
250: === js_functime.d
251: 
252:  The following script traces elapsed times for JavaScript functions. Elapsed is the time from the function entry to the return, and may include other JavaScript functions and time the JavaScript spent off the CPU. If you’d prefer other ways to calculate time spent in functions, hack away...
253: 
254: {{{
255: 
256: #!/usr/sbin/dtrace -Zs
257: /*
258:  * js_functime.d - measure JavaScript function times using DTrace.
259:  *                 Written for the Solaris Mozilla DTrace provider.
260:  *
261:  * This traces JavaScript activity from all running browers on the system
262:  * which support the mozilla DTrace provider.
263:  *
264:  * USAGE: js_functime.d         # hit Ctrl-C to end
265:  *
266:  * FIELDS:
267:  *              FILE            Filename that contained the function
268:  *              FUNCTION        JavaScript function name
269:  *              COUNT           Number of calls during this sample
270:  *              AVG(us)         Average function elapsed time, us
271:  *              SUM(us)         Total function elapsed time, us
272:  *
273:  * This measures the elapsed times for function entries to returns, and
274:  * provides some aggregated statistics. Be aware that the elapsed time for
275:  * a function is overlapping; it includes the elapsed times for child
276:  * functions that it called.
277:  *
278:  * Filename and function names are printed if available, else "<null>".
279:  */
280: #pragma ident   "@(#)js_functime.d      1.3     07/03/26 SMI"
281: 
282: #pragma D option quiet
283: 
284: this string str;
285: 
286: dtrace:::BEGIN
287: {
288:         printf("Tracing... Hit Ctrl-C to end.\n");
289:         depth = 0;
290: }
291: 
292: javascript*:::function-entry
293: {
294:         self->depth++;
295:         self->start[copyinstr(arg2), self->depth] = timestamp;
296: }
297: 
298: javascript*:::function-return
299: /(this->str = copyinstr(arg2)) != NULL && self->start[this->str, self->depth]/
300: {
301:         this->file = basename(copyinstr(arg0));
302:         this->elapsed = timestamp - self->start[this->str, self->depth];
303:         @num[this->file, this->str] = count();
304:         @eavg[this->file, this->str] = avg(this->elapsed);
305:         @esum[this->file, this->str] = sum(this->elapsed);
306:         @edist[this->str] = quantize(this->elapsed);
307:         self->start[this->file, self->depth] = 0;
308:         self->depth~--;
309: }
310: 
311: dtrace:::END
312: {
313:         normalize(@eavg, 1000);
314:         normalize(@esum, 1000);
315:         printf("ELAPSED TIME DISTRIBUTION,\n");
316:         printa(@edist);
317:         setopt("aggsortpos", "2");
318:         printf("%-33s %45s\n", "{{{___}}} OVERLAP TIMES: {{{___}}}",
319:             "{{{______}}} ELAPSED {{{_____}}}");
320:         printf("%-24s %-23s %6s %10s %12s\n", "FILE", "FUNCTION",
321:             "COUNT", "AVG(us)", "SUM(us)");
322:         printa("%-24.24s %-23.23s %@6d %@10d %@12d\n", @num, @eavg, @esum);
323: }
324: 
325: }}}
326: 
327:  Example output,
328: 
329: {{{
330: 
331: # ./js_functime.d 
332: Tracing... Hit Ctrl-C to end.
333: ^C
334: ELAPSED TIME DISTRIBUTION,
335: 
336:   getMinutes                                        
337:            value  ~------------- Distribution ~------------- count    
338:             2048 |                                         0        
339:             4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3        
340:             8192 |                                         0        
341: 
342:   getSeconds                                        
343:            value  ~------------- Distribution ~------------- count    
344:             2048 |                                         0        
345:             4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3        
346:             8192 |                                         0        
347: 
348:   getHours                                          
349:            value  ~------------- Distribution ~------------- count    
350:             8192 |                                         0        
351:            16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3        
352:            32768 |                                         0        
353: 
354:   padZero                                           
355:            value  ~------------- Distribution ~------------- count    
356:             2048 |                                         0        
357:             4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              6        
358:             8192 |@@@@@@@@@@@@@                            3        
359:            16384 |                                         0        
360: 
361:   getElementById                                    
362:            value  ~------------- Distribution ~------------- count    
363:            16384 |                                         0        
364:            32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3        
365:            65536 |                                         0        
366: 
367:   setTimeout                                        
368:            value  ~------------- Distribution ~------------- count    
369:            16384 |                                         0        
370:            32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3        
371:            65536 |                                         0        
372: 
373:   startTime                                         
374:            value  ~------------- Distribution ~------------- count    
375:           262144 |                                         0        
376:           524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3        
377:          1048576 |                                         0        
378: 
379: {{{___}}} OVERLAP TIMES: {{{___}}}                                     {{{______}}} ELAPSED {{{_____}}}
380: FILE                     FUNCTION                 COUNT    AVG(us)      SUM(us)
381: clock.html               getSeconds                   3          6           20
382: clock.html               getMinutes                   3          7           22
383: clock.html               padZero                      9          7           64
384: clock.html               getHours                     3         26           78
385: clock.html               getElementById               3         44          132
386: clock.html               setTimeout                   3         51          155
387: clock.html               startTime                    3        975         2925
388: 
389: }}}
390: 
391: The example output shows that the slowest function was startTime, which isn’t suprising as startTime contains all the other function calls. The slowest individual function was setTimeout with 3 calls at an average elapsed time of 51 microseconds per call; and the fastest function was getSeconds, which was called 3 times at an average of 6 microseconds per call.
392: 
393: Care must be taken when using a tool like this to fully understand how the time measurements are taken, and what conclusions can and can’t be made based on the output.
394: 
395: === js_objs.d
396: 
397:  This script snoops (traces) JavaScript object creation,
398: 
399: {{{
400: 
401: #!/usr/sbin/dtrace -Zs
402: /*
403:  * js_objs.d - snoop JavaScript Object creation using DTrace.
404:  *             Written for the Solaris Mozilla DTrace provider.
405:  *
406:  * This traces JavaScript activity from all running browers on the system
407:  * which support the mozilla DTrace provider.
408:  *
409:  * USAGE: js_objs.d             # hit Ctrl-C to end
410:  *
411:  * FIELDS:
412:  *              TIME            Time string
413:  *              FILE            Filename that contained the function
414:  *              LINENO          File line number where object was created
415:  *              CLASS           Class to which this new object belongs
416:  *
417:  * Filename and class names are printed if available, else "<null>".
418:  */
419: #pragma ident   "@(#)js_objs.d  1.3     07/03/26 SMI"
420: 
421: #pragma D option quiet
422: 
423: dtrace:::BEGIN
424: {
425:         printf("%-20s %24s:%-7s %s\n", "TIME", "FILE", "LINENO", "CLASS");
426: }
427: 
428: javascript*:::object-create
429: /arg2/
430: {
431:         printf("%-20Y %24.24s:%-7d %s\n", walltimestamp, 
432:             basename(copyinstr(arg0)), (int)arg3, copyinstr(arg1));
433: }
434: 
435: }}}
436: 
437:  Example output,
438: 
439: {{{
440: 
441: # ./js_objs.d
442: TIME                                     FILE:LINENO  CLASS
443: 2007 Mar 26 18:31:31               clock.html:13      Date
444: 2007 Mar 26 18:31:32               clock.html:13      Date
445: 2007 Mar 26 18:31:33               clock.html:13      Date
446: 2007 Mar 26 18:31:34               clock.html:13      Date
447: 2007 Mar 26 18:31:35               clock.html:13      Date
448: 2007 Mar 26 18:31:36               clock.html:13      Date
449: ^C
450: 
451: }}}
452: 
453: In the above output, several Date objects were created by line 13 of clock.html.
454: 
455: The following example output traces JavaScript activity by the browser interface (triggered by clicking on plugins and menus),
456: 
457: {{{
458: 
459: # ./js_objs.d
460: TIME                                     FILE:LINENO  CLASS
461: 2007 Mar 26 18:36:22               clock.html:13      Date
462: 2007 Mar 26 18:36:22                   <null>:-1      Event
463: 2007 Mar 26 18:36:22                   <null>:-1      Function
464: 2007 Mar 26 18:36:22                   <null>:-1      Function
465: 2007 Mar 26 18:36:22                   <null>:-1      MouseEvent
466: 2007 Mar 26 18:36:22              browser.xul:1       Call
467: 2007 Mar 26 18:36:22        utilityOverlay.js:380     Function
468: 2007 Mar 26 18:36:22             sb-loader.js:161     XULElement
469: 2007 Mar 26 18:36:22             sb-loader.js:167     XPCWrappedNative_NoHelper
470: 2007 Mar 26 18:36:22                   <null>:-1      Function
471: 2007 Mar 26 18:36:22             sb-loader.js:168     Function
472: 2007 Mar 26 18:36:22        utilityOverlay.js:387     nsJSCID
473: 2007 Mar 26 18:36:22        utilityOverlay.js:388     nsJSIID
474: 2007 Mar 26 18:36:22        utilityOverlay.js:388     XPCWrappedNative_NoHelper
475: 2007 Mar 26 18:36:22       nsUpdateService.js:1593    Function
476: 2007 Mar 26 18:36:22       nsUpdateService.js:1593    XPC_WN_NoMods_Proto_JSClass
477: 2007 Mar 26 18:36:22       nsUpdateService.js:1593    nsXPCComponents_Interfaces
478: 2007 Mar 26 18:36:22       nsUpdateService.js:1593    nsJSIID
479: 2007 Mar 26 18:36:22        utilityOverlay.js:388     XPCWrappedNative_NoHelper
480: 2007 Mar 26 18:36:22       nsUpdateService.js:1593    Function
481: 2007 Mar 26 18:36:22       nsUpdateService.js:1594    nsJSIID
482: 2007 Mar 26 18:36:22       nsUpdateService.js:1595    nsJSIID
483: 2007 Mar 26 18:36:22       nsUpdateService.js:1596    nsJSIID
484: 2007 Mar 26 18:36:22        utilityOverlay.js:388     XPCWrappedNative_NoHelper
485: [...]
486: 
487: }}}
488: 
489:  Sometimes the filename and line number are not available, and so "<null>" and -1 are printed to indicate this.
490: 
491: === js_objnew.d
492: 
493:  This is a simple script to summarize the number of new objects created,
494: 
495: {{{
496: 
497: #!/usr/sbin/dtrace -Zs
498: /*
499:  * js_objnew.d - measure JavaScript new objects using DTrace.
500:  *               Written for the Solaris Mozilla DTrace provider.
501:  *
502:  * This traces JavaScript activity from all running browers on the system
503:  * which support the mozilla DTrace provider.
504:  *
505:  * USAGE: js_objnew.d           # hit Ctrl-C to end
506:  *
507:  * FIELDS:
508:  *              FILE            Filename that contained the function
509:  *              CLASS           Class to which this new object belongs
510:  *              COUNT           Number of objects created
511:  *
512:  * Filename and class names are printed if available, else "<null>".
513:  */
514: #pragma ident   "@(#)js_objnew.d        1.3     07/03/26 SMI"
515: 
516: #pragma D option quiet
517: 
518: dtrace:::BEGIN
519: {
520:         printf("Tracing... Hit Ctrl-C to end.\n");
521: }
522: 
523: javascript*:::object-create
524: {
525:         @objs[basename(copyinstr(arg0)), copyinstr(arg1)] = count();
526: }
527: 
528: dtrace:::END
529: {
530:         printf(" %-24s %-36s %8s\n", "FILE", "CLASS", "COUNT");
531:         printa(" %-24.24s %-36s %@8d\n", @objs);
532: }
533: 
534: }}}
535: 
536:  Example output,
537: 
538: {{{
539: 
540: # ./js_objnew.d 
541: Tracing... Hit Ctrl-C to end.
542: ^C
543:  FILE                     CLASS                                   COUNT
544:  clock.html               Date                                        6
545: 
546: }}}
547: 
548:  Example "noisy" output,
549: 
550: {{{
551: 
552: # ./js_objnew.d 
553: Tracing... Hit Ctrl-C to end.
554: ^C
555:  FILE                     CLASS                                   COUNT
556:  browser.xul              Call                                        2
557:  menu.xml                 Array                                       2
558:  sb-loader.js             Function                                    2
559:  sb-loader.js             XPCWrappedNative_NoHelper                   2
560:  utilityOverlay.js        Function                                    2
561:  nsUpdateService.js       Array                                       4
562:  bookmarks.js             Error                                       6
563:  clock.html               Date                                        6
564:  nsUpdateService.js       XPCWrappedNative_NoHelper                   6
565:  popup.xml                Array                                       9
566:  browser.js               Function                                   18
567:  menu.xml                 XPCWrappedNative_NoHelper                  20
568:  nsUpdateService.js       Function                                   22
569:  <null>                   MouseEvent                                 28
570:  <null>                   Event                                      84
571:  menu.xml                 XULElement                                120
572:  <null>                   Function                                  231
573: 
574: }}}
575: 
576: === js_objcpu.d
577: 
578:  Sometimes the CPU time consumed to create new objects can be a performance issue. This simple script measures that time,
579: 
580: {{{
581: 
582: #!/usr/sbin/dtrace -Zs
583: /*
584:  * js_objcpu.d - measure JavaScript Object create on-CPU time using DTrace.
585:  *               Written for the Solaris Mozilla DTrace provider.
586:  *
587:  * This traces JavaScript activity from all running browers on the system
588:  * which support the mozilla DTrace provider.
589:  *
590:  * USAGE: js_objcpu.d           # hit Ctrl-C to end
591:  *
592:  * This measures the on-CPU time consumed due to JavaScript Object creation.
593:  */
594: #pragma ident   "@(#)js_objcpu.d        1.3     07/03/26 SMI"
595: 
596: #pragma D option quiet
597: 
598: dtrace:::BEGIN
599: {
600:         printf("Tracing... Hit Ctrl-C to end.\n");
601: }
602: 
603: javascritp*:::object-create-start
604: {
605:         self->vstart = vtimestamp;
606: }
607: 
608: javascript*:::object-create-done
609: /self->vstart/
610: {
611:         this->oncpu = vtimestamp - self->vstart;
612:         @dist["Object Creation on-CPU time (ns):"] = quantize(this->oncpu);
613:         @total["Total on-CPU time (us):"] = sum(this->oncpu);
614:         self->vstart = 0;
615: }
616: 
617: dtrace:::END
618: {
619:         normalize(@total, 1000);
620: }
621: 
622: }}}
623: 
624:  Example output,
625: 
626: {{{
627: 
628: # ./js_objcpu.d 
629: Tracing... Hit Ctrl-C to end.
630: ^C
631: 
632:   Object Creation on-CPU time (ns):                 
633:            value  ~------------- Distribution ~------------- count    
634:              256 |                                         0        
635:              512 |@@@@@@@@@                                92       
636:             1024 |@@@@@@@@@@@@@@@@@@@@@@@@                 235      
637:             2048 |@@@@                                     36       
638:             4096 |@                                        13       
639:             8192 |@@                                       19       
640:            16384 |                                         0        
641:            32768 |                                         1        
642:            65536 |                                         0        
643: 
644:   Total on-CPU time (us):                                         824
645: 
646: }}}
647: 
648: === js_objgc.d
649: 
650:  The following script is useful to check the behaviour of garbage collect. It tallys the number of objects and prints a summary every second. By watching the output for a while (several minutes or more), steadily increasing object counts into the thousands may be evidence of an object leak.
651: 
652: {{{
653: 
654: #!/usr/sbin/dtrace -Zs
655: /*
656:  * js_objgc.d - measure JavaScript Object GC using DTrace.
657:  *              Written for the Solaris Mozilla DTrace provider.
658:  *
659:  * This traces JavaScript activity from all running browers on the system
660:  * which support the mozilla DTrace provider.
661:  *
662:  * USAGE: js_objgc.d            # hit Ctrl-C to end
663:  *
664:  * FIELDS:
665:  *              FILE            Filename that contained the function
666:  *              CLASS           Class to which this new object belongs
667:  *              TOTAL           Object entropy (positive == uncollected)
668:  *
669:  * This script provides information on which objects are not being garbage
670:  * collected, an issue which causes the browser to steadily leak memory.
671:  * We trace object creation (+1) and destruction (-1), and provide a
672:  * summary each second of the running tally of the object class and
673:  * originating filename. If over the period of several minutes an object
674:  * type is still steadily increasing, then that would be of interest.
675:  * Be patient, depending on the rate of object creation, it can take over
676:  * ten minutes for garbage collect to kick in.
677:  *
678:  * Filename and class names are printed if available, else "<null>".
679:  *
680:  * NOTE: there are other Things that GC handles, other than Objects; extra
681:  * probes can be added to trace them, should the need arise.
682:  */
683: #pragma ident   "@(#)js_objgc.d 1.3     07/03/26 SMI"
684: 
685: #pragma D option quiet
686: #pragma D option dynvarsize=32m
687: 
688: dtrace:::BEGIN
689: {
690:         printf("Tracing... Hit Ctrl-C to end.\n");
691: }
692: 
693: javascript*:::object-create
694: /arg2/
695: {
696:         this->file = basename(copyinstr(arg0));
697:         @objs[this->file, copyinstr(arg1)] = sum(1);
698:         filename[arg2] = this->file;
699: }
700: 
701: javascript*:::object-finalize
702: /filename[arg2] == NULL/
703: {
704:         /* these are caused by dynvardrops. increase dynvarsize */
705:         @objs["<missed>", copyinstr(arg1)] = sum(-1);
706: }
707: 
708: javascript*:::object-finalize
709: /filename[arg2] != NULL/
710: {
711:         @objs[filename[arg2], copyinstr(arg1)] = sum(-1);
712:         filename[arg2] = 0;
713: }
714: 
715: profile:::tick-1sec,
716: dtrace:::END
717: {
718:         printf("\n %-24s %-36s %8s\n", "FILE", "CLASS", "TOTAL");
719:         printa(" %-24.24s %-36s %@8d\n", @objs);
720: }
721: 
722: }}}
723: 
724:  Example output,
725: 
726: {{{
727: 
728: # ./js_objgc.d 
729: Tracing... Hit Ctrl-C to end.
730: 
731:  FILE                     CLASS                                   TOTAL
732:  fastclock.html           Date                                       88
733: 
734:  FILE                     CLASS                                   TOTAL
735:  fastclock.html           Date                                      173
736: 
737:  FILE                     CLASS                                   TOTAL
738:  fastclock.html           Date                                      259
739: 
740:  FILE                     CLASS                                   TOTAL
741:  fastclock.html           Date                                      345
742: 
743:  FILE                     CLASS                                   TOTAL
744:  nsMicrosummaryService.js Array                                       1
745:  nsMicrosummaryService.js Function                                    3
746:  nsMicrosummaryService.js XPCWrappedNative_NoHelper                   4
747:  fastclock.html           Date                                      431
748: 
749: [...time passes...]
750: 
751:  FILE                     CLASS                                   TOTAL
752:  <null>                   MouseEvent                                  1
753:  browser.js               Array                                       1
754:  browser.js               CSSStyleDeclaration                         1
755:  browser.js               ComputedCSSStyleDeclaration                 1
756:  browser.js               XPCNativeWrapper                            1
757:  browser.xul              XPCNativeWrapper                            1
758:  popup.xml                Array                                       1
759:  browser.js               Constructor                                 2
760:  browser.js               XPC_WN_ModsAllowed_Proto_JSClass            2
761:  nsMicrosummaryService.js Array                                       4
762:  nsMicrosummaryService.js Function                                    6
763:  nsMicrosummaryService.js XPCWrappedNative_NoHelper                   7
764:  <null>                   Function                                   14
765:  browser.js               Function                                   17
766:  fastclock.html           Date                                     5321
767: 
768:  FILE                     CLASS                                   TOTAL
769:  <missed>                 Function                                 -172
770:  <missed>                 Date                                     -152
771:  <missed>                 XPCWrappedNative_NoHelper                 -33
772:  <missed>                 Object                                    -19
773:  <missed>                 Attr                                      -15
774:  <missed>                 Array                                     -14
775:  <missed>                 Call                                       -8
776:  <missed>                 XPC_WN_NoMods_Proto_JSClass                -7
777:  <missed>                 BarProp                                    -6
778:  <missed>                 BoxObject                                  -1
779:  <missed>                 HTMLDivElement                             -1
780:  <missed>                 Iterator                                   -1
781:  <missed>                 NamedNodeMap                               -1
782:  <missed>                 XULElement                                 -1
783:  <null>                   MouseEvent                                  0
784:  browser.js               Array                                       0
785:  browser.js               CSSStyleDeclaration                         0
786:  browser.js               ComputedCSSStyleDeclaration                 0
787:  browser.js               XPCNativeWrapper                            0
788:  nsMicrosummaryService.js Array                                       0
789:  nsMicrosummaryService.js Function                                    0
790:  nsMicrosummaryService.js XPCWrappedNative_NoHelper                   0
791:  popup.xml                Array                                       0
792:  browser.xul              XPCNativeWrapper                            1
793:  fastclock.html           HTMLDivElement                              1
794:  browser.js               Constructor                                 2
795:  browser.js               XPC_WN_ModsAllowed_Proto_JSClass            2
796:  <null>                   Function                                    3
797:  browser.js               Function                                    6
798:  fastclock.html           Date                                        7
799: 
800: }}}
801: 
802: In the above output, the Date object from fastclock.html steadily increased until there were 5321 of them, then the following output shows that the Date object count has dropped to 7 - this shows garbage collect working. Also in the final output are many negative count objects with a "<missed>" filename - these are objects that were already in memory when tracing began (so their count was zero), and we traced their destruction (so they count became negative).
OpenSolaris

Top Menu

Wiki code for JavaScript Tracing

Search

Collectives

Community Group

Project

User Group

Subsites

Project mozilla-dtrace Pages
