9 ms·

Timing the time it takes to parse time

109 points by yread 10y ago

userbinator 10y ago
The dates are strictly formatted, the values are stored as UTF8 and there are no cultures to consider. I wonder what the speedup will be from omitting all the validation and associated branching and just picking the values out directly. Chances are that you won't see more than one date format in the same input either. Another strategy I'd use is to parallelise the digitisation; assuming the YYYY-MM-DDTHH:mm:ss format, it'd start off something like this (untested, but should be close if not completely correct): Y = *(uint32_t*)s - 0x30303030; M = *(uint16_t*)(s+5) - 0x3030; D = *(uint16_t*)(s+8) - 0x3030; Y = 100 * ((10 * (Y >> 24) + (Y >> 16)) & 255) + ((10 * (Y >> 8) + Y) & 255); M = (10 * (M >> 8) + M) & 255; D = (10 * (D >> 8) + D) & 255; It should be possible to reduce the year computation to 2 multiplications, at the expense of several more masking operations. Around 50-100 clock cycles per full datetime should be possible, which is in the few-dozen-ns range on a GHz-clock CPU. Probably could go a bit faster still if you start bringing in the SSE...
- avian 10y ago
  This is quite clever. The catch is that it assumes implementation specific details (like a little-endian architecture) while OP's code is (probably) portable C.
  - dimman 10y ago
    Which part are you referring to? Bit operations etc isn't affected by endianess. It looks like it would only potentially be a problem if input is coming from another system (haven't looked at where input comes from or what format/type).
    - avian 10y ago
      I was referring to this part: Y = *(uint32_t*)s - 0x30303030; By casting a string to a uint32_t, you are assuming the memory layout of uint32_t. Y will have a different value depending on architecture. E.g. on a typical little-endian you will get 0x06010002. On big-endian you will get 0x02000106. I'm talking about C, however. I didn't notice the post is talking about C#. Things might be better defined there.
      - JoeAltmaier 10y ago
        Regardless of layout, that subtraction will have the same effect on most printable characters. An identical effect on digits.
        avian 10y ago
        The cast is the problematic part, not the subtraction.
        JoeAltmaier 10y ago
        If there is no carry, then I don't understand. Four bytes will have the same value deducted. regardless of the byte order. If there is no carry implication (all are digits) then there is no issue.
        huhtenberg 10y ago
        On RISC platforms *(uint32_t*)s will get you a SIGBUS if s is not aligned to a 4-byte boundary. Though that's another issue, not what OP was referring to.
        zeusk 10y ago
        ARM has unaligned access since v6 (introduced in 2001); if you're on linux, unaligned access will be patched by the kernel (as was the case prior ARMv6 and even for MIPS afaik). Anyway, the point of his post was about possible gains from removing validation, not about being portable or production code.
    - to3m 10y ago
      Y>>24 will be the byte at +3 on a little-endian system, or +0 on a big-endian system. It's therefore the digit in the 10^0 column in the former case, or the 10^3 column in the latter. So it actually looks like it currently assumes a big-endian system.
  - yread 10y ago
    OP's code is unsafe C#
- yread 10y ago
  Since you're mostly interested in only this century you could probably use lookup tables for everything.
douglasfshearer 10y ago
Simple optimisations like this shave minutes off the runtime of log parsing and data import jobs I run. I do lots of this in Ruby [0], and often write a custom parser when I know that dates or times will be of regular form. As a bonus I get to golf different methods of doing the parsing against each other, using microbenchmarks. [0] https://gist.github.com/dougal/e972b26cd0293f99b41896e7d89c070e https://gist.github.com/dougal/e972b26cd0293f99b41896e7d89c0...
thomas-st 10y ago
I had similar issues in Python, where the available date parsers weren't fast enough. With my C module, I got 320ns, which was 62x faster than Python's less flexible strptime. See https://github.com/closeio/ciso8601/ https://github.com/closeio/ciso8601/ for my benchmarks.
- logicallee 10y ago
  I don't get it. In 1 single millisecond, a processor does on the order of a million operations, and if it's being run that tightly the code should be close to the CPU, perhaps in L2 or L3 cache -- what on earth requires parsing 62x faster than that, for date parsing? 320 ns * 62 is 19 microseconds for the version that yuo said was too slow for you, which is 0.019 milliseconds. Like, what even generates formated date data that fast, or why can't you wait 0.019 ms to parse it out again? Genuine question. EDIT: I got downvoted, but it's just a question. If it's logs, is it old logs, or streaming from somewheere? Rather than speculate I'd like to hear the actual answer from thomas-st for their use case. 62x is just under 1.8 orders of magnitude, so I wouldn't think it matters in comparison with typical CPU and RAM speeds, disk, network, or other bottlenecks...
  - thomas-st 10y ago
    See https://hack.close.io/posts/ciso8601 https://hack.close.io/posts/ciso8601 on the use case.
    - logicallee 10y ago
      that's amazing, and incredibly surprising. It's one of the operations I would ahve thought was essentiall free, and completely dwarfed by other bottlenecks and latencies. I mean it's just a few characters, right! I'm really suprised by the result you report in your link - thanks for writing it up!
  - jbrooksuk 10y ago
    Parsing logs? Geo location?
  - 10y ago
willvarfar 10y ago
I do a lot of log crunching with pypy, and datetime.strftime is a really big part of the cost. I wish someone could contribute faster datetime routines to the standard CPython and pypy. Other parts that are always hot include split() and string concatenation. Java compilers can substitute StringBuffers when they see naive string concatenation, but in Python there's no easy way to build a string in a complex loop and you end up putting string fragments into a list and then finally join()ing them. Madness!
- vietjtnguyen 10y ago
  For your point about Python string concatenation, I believe that's what io.StringIO is for (https://docs.python.org/3/library/io.html#io.StringIO https://docs.python.org/3/library/io.html#io.StringIO).
  - maxerickson 10y ago
    If you are using CPython 2.4 or 2.5 or later, use the clearest code. In earlier versions using join on a list was faster, but the inplace add operation was optimized, turning the stuff about string.join being faster mostly into mythlore. https://bugs.python.org/issue980695 https://bugs.python.org/issue980695 PyPy and other implementations may do better with the join idiom though. Of course someone with code spending a lot of time on joining strings can measure which is best for their situation, but += is fine for most things.
    - willvarfar 10y ago
      http://pypy.org/performance.html http://pypy.org/performance.html says "String concatenation is expensive" and suggests using join() in loops. Its an old problem https://bitbucket.org/pypy/pypy/issues/1925/very-slow-string-concatenation https://bitbucket.org/pypy/pypy/issues/1925/very-slow-string... So whilst pypy is otherwise much faster than CPython, its missing of this kind of optimisation is why actually CPython can be faster for parsing my logs. I know about this because I've been bitten by it :)
- fnord123 10y ago
lorenzhs 10y ago
Those plots are confusing - plotting time and standard deviation as two bars next to each other is odd. It would be much better if the plot used error bars, e.g. like this: https://egret.psychol.cam.ac.uk/statistics/local_copies_of_sources_Cardinal_and_Aitken_ANOVA/errorbars_files/graph1.gif https://egret.psychol.cam.ac.uk/statistics/local_copies_of_s... . Otherwise it's very hard to tell whether the difference between two implementations is just noise or not. And if the numbers are so large, adjust the scale. Don't plot thousands of nanoseconds—plot microseconds! I'm not faulting the author for their plots—making good plots is hard!—but good articles suffer when the data is presented in such ways.
- DougBTX 10y ago
  Reading further into the article, that chart is a setup for the "new times are smaller than the old error bars" punch line.
necessity 10y ago
Forget parsing time, just taking the time takes an awful lot of time. Try measuring a very quick routine (a few nanoseconds) with clock_gettime - you have to do various calls and take a mean because of resolution issues, and also measure and reduce the overhead of the logging routine. This becomes a real issue because taking a mean of various calls is different than doing just one call (cache, branch prediction, etc). You could add something else inside the loop but then your fast routine becomes a tiny part of what you are measuring and the relative error explodes. It is simply not possible to benchmark routines that take just a few nanoseconds precisely and exactly with userspace routines. There are whitepapers from Intel on how to do this on their processors with a kernel module to disable preemption and IRQs and read the TSC directly with asm, but then you can't have userspace stuff... Benchmarking quick stuff is no fun.
- Beltiras 10y ago
  Hardest thing I ever had to profile had to do with accessing Postgres from Python. I needed the cold-start time. I ended up kinda fuzzing it to find an estimate. Filled a table with proper data and accessed random keys to find an average. Even then some optimization occurred.
tstack 10y ago
Parsing time is a huge cost when the Logfile Navigator (http://lnav.org http://lnav.org) is parsing log files. The libc strptime() is terribly slow, so I wrote a simple compiler[1] that would spit out inlined C++ code for parsing a particular time format (e.g. "%Y-%m-%dT%H:%M:%S.%f%z"). Coupled with the fact that a time format is not going to differ across log lines in a single file, lnav is able to lock onto a date format and parse all the lines in a file fairly quickly. [1] - https://github.com/tstack/lnav/blob/master/src/ptimec.cc https://github.com/tstack/lnav/blob/master/src/ptimec.cc

109 points by yread 10y ago

The dates are strictly formatted, the values are stored as UTF8 and there are no cultures to consider. I wonder what the speedup will be from omitting all the validation and associated branching and just picking the values out directly. Chances are that you won't see more than one date format in the same input either. Another strategy I'd use is to parallelise the digitisation; assuming the YYYY-MM-DDTHH:mm:ss format, it'd start off something like this (untested, but should be close if not completely correct): Y = *(uint32_t*)s - 0x30303030; M = *(uint16_t*)(s+5) - 0x3030; D = *(uint16_t*)(s+8) - 0x3030; Y = 100 * ((10 * (Y >> 24) + (Y >> 16)) & 255) + ((10 * (Y >> 8) + Y) & 255); M = (10 * (M >> 8) + M) & 255; D = (10 * (D >> 8) + D) & 255; It should be possible to reduce the year computation to 2 multiplications, at the expense of several more masking operations. Around 50-100 clock cycles per full datetime should be possible, which is in the few-dozen-ns range on a GHz-clock CPU. Probably could go a bit faster still if you start bringing in the SSE...

avian 10y ago
This is quite clever. The catch is that it assumes implementation specific details (like a little-endian architecture) while OP's code is (probably) portable C.
- dimman 10y ago
  Which part are you referring to? Bit operations etc isn't affected by endianess. It looks like it would only potentially be a problem if input is coming from another system (haven't looked at where input comes from or what format/type).
  - avian 10y ago
    I was referring to this part: Y = *(uint32_t*)s - 0x30303030; By casting a string to a uint32_t, you are assuming the memory layout of uint32_t. Y will have a different value depending on architecture. E.g. on a typical little-endian you will get 0x06010002. On big-endian you will get 0x02000106. I'm talking about C, however. I didn't notice the post is talking about C#. Things might be better defined there.
    - JoeAltmaier 10y ago
      Regardless of layout, that subtraction will have the same effect on most printable characters. An identical effect on digits.
      - avian 10y ago
        The cast is the problematic part, not the subtraction.
        JoeAltmaier 10y ago
        If there is no carry, then I don't understand. Four bytes will have the same value deducted. regardless of the byte order. If there is no carry implication (all are digits) then there is no issue.
        huhtenberg 10y ago
        On RISC platforms *(uint32_t*)s will get you a SIGBUS if s is not aligned to a 4-byte boundary. Though that's another issue, not what OP was referring to.
        zeusk 10y ago
        ARM has unaligned access since v6 (introduced in 2001); if you're on linux, unaligned access will be patched by the kernel (as was the case prior ARMv6 and even for MIPS afaik). Anyway, the point of his post was about possible gains from removing validation, not about being portable or production code.
  - to3m 10y ago
    Y>>24 will be the byte at +3 on a little-endian system, or +0 on a big-endian system. It's therefore the digit in the 10^0 column in the former case, or the 10^3 column in the latter. So it actually looks like it currently assumes a big-endian system.
- yread 10y ago
  OP's code is unsafe C#
yread 10y ago
Since you're mostly interested in only this century you could probably use lookup tables for everything.

douglasfshearer 10y ago

Simple optimisations like this shave minutes off the runtime of log parsing and data import jobs I run. I do lots of this in Ruby [0], and often write a custom parser when I know that dates or times will be of regular form. As a bonus I get to golf different methods of doing the parsing against each other, using microbenchmarks. [0] https://gist.github.com/dougal/e972b26cd0293f99b41896e7d89c070e https://gist.github.com/dougal/e972b26cd0293f99b41896e7d89c0...

thomas-st 10y ago

I had similar issues in Python, where the available date parsers weren't fast enough. With my C module, I got 320ns, which was 62x faster than Python's less flexible strptime. See https://github.com/closeio/ciso8601/ https://github.com/closeio/ciso8601/ for my benchmarks.

logicallee 10y ago
I don't get it. In 1 single millisecond, a processor does on the order of a million operations, and if it's being run that tightly the code should be close to the CPU, perhaps in L2 or L3 cache -- what on earth requires parsing 62x faster than that, for date parsing? 320 ns * 62 is 19 microseconds for the version that yuo said was too slow for you, which is 0.019 milliseconds. Like, what even generates formated date data that fast, or why can't you wait 0.019 ms to parse it out again? Genuine question. EDIT: I got downvoted, but it's just a question. If it's logs, is it old logs, or streaming from somewheere? Rather than speculate I'd like to hear the actual answer from thomas-st for their use case. 62x is just under 1.8 orders of magnitude, so I wouldn't think it matters in comparison with typical CPU and RAM speeds, disk, network, or other bottlenecks...
- thomas-st 10y ago
  See https://hack.close.io/posts/ciso8601 https://hack.close.io/posts/ciso8601 on the use case.
  - logicallee 10y ago
    that's amazing, and incredibly surprising. It's one of the operations I would ahve thought was essentiall free, and completely dwarfed by other bottlenecks and latencies. I mean it's just a few characters, right! I'm really suprised by the result you report in your link - thanks for writing it up!
- jbrooksuk 10y ago
  Parsing logs? Geo location?
- 10y ago

willvarfar 10y ago

I do a lot of log crunching with pypy, and datetime.strftime is a really big part of the cost. I wish someone could contribute faster datetime routines to the standard CPython and pypy. Other parts that are always hot include split() and string concatenation. Java compilers can substitute StringBuffers when they see naive string concatenation, but in Python there's no easy way to build a string in a complex loop and you end up putting string fragments into a list and then finally join()ing them. Madness!

vietjtnguyen 10y ago
For your point about Python string concatenation, I believe that's what io.StringIO is for (https://docs.python.org/3/library/io.html#io.StringIO https://docs.python.org/3/library/io.html#io.StringIO).
- maxerickson 10y ago
  If you are using CPython 2.4 or 2.5 or later, use the clearest code. In earlier versions using join on a list was faster, but the inplace add operation was optimized, turning the stuff about string.join being faster mostly into mythlore. https://bugs.python.org/issue980695 https://bugs.python.org/issue980695 PyPy and other implementations may do better with the join idiom though. Of course someone with code spending a lot of time on joining strings can measure which is best for their situation, but += is fine for most things.
  - willvarfar 10y ago
    http://pypy.org/performance.html http://pypy.org/performance.html says "String concatenation is expensive" and suggests using join() in loops. Its an old problem https://bitbucket.org/pypy/pypy/issues/1925/very-slow-string-concatenation https://bitbucket.org/pypy/pypy/issues/1925/very-slow-string... So whilst pypy is otherwise much faster than CPython, its missing of this kind of optimisation is why actually CPython can be faster for parsing my logs. I know about this because I've been bitten by it :)
fnord123 10y ago

lorenzhs 10y ago

Those plots are confusing - plotting time and standard deviation as two bars next to each other is odd. It would be much better if the plot used error bars, e.g. like this: https://egret.psychol.cam.ac.uk/statistics/local_copies_of_sources_Cardinal_and_Aitken_ANOVA/errorbars_files/graph1.gif https://egret.psychol.cam.ac.uk/statistics/local_copies_of_s... . Otherwise it's very hard to tell whether the difference between two implementations is just noise or not. And if the numbers are so large, adjust the scale. Don't plot thousands of nanoseconds—plot microseconds! I'm not faulting the author for their plots—making good plots is hard!—but good articles suffer when the data is presented in such ways.

DougBTX 10y ago
Reading further into the article, that chart is a setup for the "new times are smaller than the old error bars" punch line.

necessity 10y ago

Forget parsing time, just taking the time takes an awful lot of time. Try measuring a very quick routine (a few nanoseconds) with clock_gettime - you have to do various calls and take a mean because of resolution issues, and also measure and reduce the overhead of the logging routine. This becomes a real issue because taking a mean of various calls is different than doing just one call (cache, branch prediction, etc). You could add something else inside the loop but then your fast routine becomes a tiny part of what you are measuring and the relative error explodes. It is simply not possible to benchmark routines that take just a few nanoseconds precisely and exactly with userspace routines. There are whitepapers from Intel on how to do this on their processors with a kernel module to disable preemption and IRQs and read the TSC directly with asm, but then you can't have userspace stuff... Benchmarking quick stuff is no fun.

Beltiras 10y ago
Hardest thing I ever had to profile had to do with accessing Postgres from Python. I needed the cold-start time. I ended up kinda fuzzing it to find an estimate. Filled a table with proper data and accessed random keys to find an average. Even then some optimization occurred.

tstack 10y ago

Parsing time is a huge cost when the Logfile Navigator (http://lnav.org http://lnav.org) is parsing log files. The libc strptime() is terribly slow, so I wrote a simple compiler[1] that would spit out inlined C++ code for parsing a particular time format (e.g. "%Y-%m-%dT%H:%M:%S.%f%z"). Coupled with the fact that a time format is not going to differ across log lines in a single file, lnav is able to lock onto a date format and parse all the lines in a file fairly quickly. [1] - https://github.com/tstack/lnav/blob/master/src/ptimec.cc https://github.com/tstack/lnav/blob/master/src/ptimec.cc