Today I was working on my TBtracer plugin, which is humming along nicely BTW, some of the new features recently included are:
- full response for HTTP requests in log,
- CSS rules for both HTTP head and body,
- better organization of high-resolution timestamps in conjunction with HTTP lines (timestamps for both request and response are recorded at the exact moment the notification first hits my code),
- able to select which columns are shown in log,
- custom date format string for timestamps.
The first script I tried looks like this found here. As you can see from the code, the basic idea is to have a function for every possible token which returns a string, then iterate over the pattern, call the appropriate function for each token and throw together the returned strings.
The next one, I found was this found here. The idea here is to use String’s replace method with a function for each possible token. And it has an array named flags where each possible token is present with the actual value, which then gets substituted into the string. I actually liked this at first, because I think the tokens make more sense than the standard PHP format specifiers.
Looking around for a parser, I found this script at this site, which does both formatting as well as parsing with the same format specifiers. For the formatting it also uses functions to return the value for each token, but instead of just using the function each time, it builds the code as a string, eval’s it and then caches that function for later use. And I know we all know that eval is evil, but still: sometimes it’s actually useful, for example in this case. The parser does the same in the other direction, but it obviously uses Regexes for the parsing and also caches the resulting function.
I first tested a short format string, calling the formatter 1000x for each script. Then I used the formats that came with each formatter to give them a random pattern each time, and lastly I changed the patterns that they produce the same output for each and used the same random one for each script. The numbers given here represent that last run.
- Formatting with functions: (own time) 9.656ms, (total time) 16.622ms, (avg) 0.017ms, (min) 0.006ms, (max) 0.092ms.
- Formatting with replace: (own time) 0.744ms, (total time) 73.148ms, (avg) 0.073ms, (min) 0.062ms, (max) 0.299ms.
- Format cached functions: (own time) 1.718ms, (total time) 13.899ms, (avg) 0.014ms, (min) 0.003ms, (max) 0.578ms.
Explanation: “own time” means time spent in the function excluding function calls made from within that function, “total time” means the total time spent including function calls, and then the minimum, avg and max for the total time.
Summary: We can clearly see that using String.replace in that way is not very efficient, because when you inspect the code you see that each token gets evaluated for the date in question even if it’s not used, which results in a lot of overhead. Both number 1 and 3 fare pretty well, and very close to each other within 3millisecons of each other for 1000 runs! So we can conclude that caching the functions is advantageous even if only by a small margin, and that eval is not always evil. Firefox’s tracemonkey most likely compiles all functions for both methods to native code and caches them, which explains their similar runtimes.
As a last word, the date parser from number 3 is about half as fast as its own formatter, meaning that it is not a lot slower than the second best formatter and definitely faster than number 2’s formatter.