Disclaimer: I am not a Javascript expert. I don’t even play one on TV.
Everybody knows that logging isn’t free, don’t they? Well I don’t think that they do and for a lot of beginner to intermediate level developers I can’t really fault them for it. While you’re debugging it appears that log messages show up instantly so it is easy to forget that there is in fact a cost associated with producing them.
What is less obvious is that even when you “disable” your logging it still incurs a cost and that cost may be significantly larger than you think. The two main issues I’ve seen that often cause this large expense are:
- Methods that generate log messages
- Inline generation of strings
The first, methods that generate log messages, occurs when you need to do a bit of processing in order to make a meaningful log message. For example, you might need to know how far you are through a loop so you write a function called generateFormattedProgress
that takes the number of loops you’re going to go through and the current loop counter as parameters. generateFormattedProgress
generates a tidy little string that might loop like this [8% complete (currently on iteration 80,001 of 1,000,000)]
.
The second, inline generation of strings, happens when you need to do something a bit simpler like displaying a loop counter. You might build a string like this "Loop: " + loop_counter
and then log it.
In both of these cases you get bitten by the less obvious issue I mentioned above when you disable logging. To be completely concrete about this imagine your logger is called like this:
Case #1:
1
|
|
Case #2:
1
|
|
Even if you replace console.log
with a function that just immediately returns you will, in most cases, still be forcing the machine to call generateFormattedProgress
and perform the string concatenation only to throw the results away. This is where the overhead comes in.
Borrowing from some other languages I came up with an idea to reduce this burden. Unfortunately it is a bit ugly but it does give you a decent performance boost. The idea is that instead of always calling the logging code at runtime you wrap your logging statements in anonymous functions and pass those to the logger. The logger can then decide if it needs to run them and if it doesn’t then it never calls the code inside of the anonymous function.
Your log statements go from looking like the statements above to statements like this:
Case #1:
1
|
|
Case #2:
1
|
|
Some test code is below to illustrate the difference in performance. On my machine running 100,000 iterations I get the following results in Chrome 37.0.2062.94:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 |
|
So here we see that we cut the runtime by at least two orders of magnitude going from a little over 1.9 seconds for each case to less than 20 milliseconds for each case. Does logging affect your Javascript application enough to use this pattern? Is this an anti-pattern? Are you already doing this or something similar? Post a message in the comments and lets discuss it!
Sample test code:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 |
|