Wednesday, July 25th, 2007

End-to-End Tracing of Ajax/Java Applications Using DTrace

Category: Utility

We posted about using DTrace to profile Firefox in the past, and today Amit Hurvitz published a piece on Ajax, DTrace and Where They Meet.

The article walks you through setting up dtrace on an an Ajax tracing example and then goes into detail on tracing Ajax and Java call flow where they are tracing the call flow of the JavaScript functions and the Java servlet methods, which responds to the Ajax calls using the script:

javascript

  1. #!/usr/sbin/dtrace -Zs
  2.  
  3. #pragma D option quiet
  4. #pragma D option switchrate=10
  5.  
  6. dtrace:::BEGIN
  7. {
  8.         jsIndent = 0;
  9.         jsFile = "ajax-validation";
  10.         javaMethodBoundary= "doGet";
  11.         startTimestamp = timestamp;
  12. }
  13.  
  14. *mozilla$1:::js_function-entry
  15. /basename(copyinstr(arg0)) == jsFile/
  16. {
  17.         jsIndent += 2;
  18.         printf("%*s -> %s:%s (JavaScript)(elapsed ms: %d)\n", jsIndent, "",
  19.             jsFile, copyinstr(arg2), (timestamp - startTimestamp) / 1000);
  20. }
  21.  
  22. *mozilla$1:::js_function-return
  23. /basename(copyinstr(arg0)) == jsFile/
  24. {
  25.         printf("%*s < - %s:%s (JavaScript)(elapsed ms: %d)\n", jsIndent, "",
  26.             jsFile, copyinstr(arg2), (timestamp - startTimestamp) / 1000);
  27.         jsIndent -= 2;
  28. }
  29.  
  30.  
  31. hotspot$2:::method-entry
  32. {
  33.         self->strPtr = (char *)copyin(arg1, args[2]+1);
  34.         self->strPtr[(int)args[2]] = '\0';
  35.         self->classStr = (string)self->strPtr;
  36.         self->strPtr = (char *)copyin(arg3, (int)args[4]+1);
  37.         self->strPtr[(int)args[4]] = '\0';
  38.         self->methodStr = (string)self->strPtr;
  39. }
  40.  
  41. hotspot$2:::method-entry
  42. /javaMethodBoundary == self->methodStr/
  43. {
  44.         self->interested = 1;
  45.         self->indent = 0;
  46. }
  47.  
  48. hotspot$2:::method-entry
  49. /self->interested/
  50. {
  51.         self->indent += 2;
  52.         printf("%*s -> %s:%s (Java)(elapsed ms: %d)\n", self->indent, "",
  53.             self->classStr, self->methodStr, (timestamp - startTimestamp) / 1000);
  54. }
  55.  
  56. hotspot$2:::method-return
  57. {
  58.         self->strPtr = (char *)copyin(arg1, args[2]+1);
  59.         self->strPtr[(int)args[2]] = '\0';
  60.         self->classStr = (string)self->strPtr;
  61.         self->strPtr = (char *)copyin(arg3, (int)args[4]+1);
  62.         self->strPtr[(int)args[4]] = '\0';
  63.         self->methodStr = (string)self->strPtr;
  64. }
  65.  
  66. hotspot$2:::method-return
  67. /self->interested/
  68. {
  69.         printf("%*s < - %s:%s (Java)(elapsed ms: %d)\n", self->indent, "",
  70.             self->classStr, self->methodStr, (timestamp - startTimestamp) / 1000);
  71.         self->indent -= 2;
  72. }
  73.  
  74. hotspot$2:::method-return
  75. /javaMethodBoundary == self->methodStr/
  76. {
  77.         self->interested = 0;
  78.         /* exit(0); */
  79. }

It then continues to show timings of methods and such. This may not be the simplest solution for debugging, but at least you can get inside the black box when you need too.

Posted by Dion Almaer at 12:14 pm
Comment here

+----
1.4 rating from 200 votes

Comments Here »

Comments feed TrackBack URI

Leave a comment

You must be logged in to post a comment.