You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
The call stack tells us a story -- reading from the bottom up, it lets us describe
41
+
what is happening inside the service code. A developer, even one unfamiliar with the
42
+
source code, should be able to look at this call stack to craft a narrative like:
43
+
> We are getting the outcome of a game. We leverage the DoorChecker to
44
+
> see if something is the winner, but the check for door two somehow issues
45
+
> a precheck() that, for some reason, is deciding to sleep for a long time.
46
+
47
+
Our workshop application is left intentionally simple -- a real-world service might see the
48
+
thread being sampled during a database call or calling into an un-traced external service.
49
+
It is also possible that a slow span is executing a complicated business process,
50
+
in which case maybe none of the stack traces relate to each other at all.
51
+
52
+
The longer a method or process is, the greater chance we will have call stacks
53
+
sampled during its execution.
54
+
55
+
### Let's Fix That Bug
56
+
57
+
By using the profiling tool, we were able to determine that our application is slow
58
+
when issuing the `DoorChecker.precheck()` method from inside `DoorChecker.checkDoorTwo()`.
59
+
Let's open the `doorgame/src/main/java/com/splunk/profiling/workshop/DoorChecker.java` source file in our editor.
60
+
61
+
By quickly glancing through the file, we see that there are methods for checking
62
+
each door, and all of them call `precheck()`. In a real service, we might be uncomfortable
63
+
simply removing the `precheck()` call because there could be unseen/unaccounted side
64
+
effects.
65
+
66
+
Down on line 29 we see the following:
67
+
```java
68
+
privateboolean checkDoorTwo(GameInfo gameInfo) {
69
+
precheck(2);
70
+
return gameInfo.isWinner(2);
71
+
}
72
+
73
+
privatevoid precheck(int doorNum) {
74
+
long extra = (int)Math.pow(70, doorNum);
75
+
sleep(300+ extra);
76
+
}
77
+
```
78
+
79
+
With our developer hat on, we notice that the door number is zero based, so
80
+
the first door is 0, the second is 1, and the 3rd is 2 (this is conventional).
81
+
The `extra` value is used as extra/additional sleep time, and it is computed by taking
82
+
`70^doorNum` (`Math.pow` performs an exponent calculation). That's odd, because this means:
83
+
* door 0 => 70^0 => 1ms
84
+
* door 1 => 70^1 => 70ms
85
+
* door 2 => 70^2 => 4900ms
86
+
87
+
We've found the root cause of our slow bug! This also explains why the first two doors
88
+
weren't ever very slow.
89
+
90
+
We have a quick chat with our product manager and team lead, and we agree that the `precheck()`
91
+
method must stay but that the extra padding isn't required. Let's remove the `extra` variable
92
+
and make `precheck` now read like this:
93
+
94
+
```java
95
+
privatevoid precheck(int doorNum) {
96
+
sleep(300);
97
+
}
98
+
```
99
+
100
+
Now all doors will have a consistent behavior. Save your work and then rebuild and redeploy the application using the following command:
101
+
102
+
```
103
+
cd workshop/profiling
104
+
./4-redeploy-doorgame.sh
105
+
```
106
+
107
+
Once the application has been redeployed successfully, visit The Door Game again to confirm that your fix is in place:
108
+
`http://<your IP address>:81`
109
+
110
+
## What did we accomplish?
111
+
112
+
* We learned how to view a series of call stacks captured during a Span.
113
+
* We learned how the call stack can tell us a story and point us to suspect lines of code.
114
+
* We identified the slow code and fixed it to make it faster.
115
+
116
+
In the next section, we'll explore how to enable the memory profiling component of AlwaysOn Profiling, which can tell us which objects are consuming the most heap memory.
0 commit comments