Can't find why this datetime test fails, in F#

Question

I have the following function, which was made with the help of some people here:

module DateTimeFormatter =

    let mutable year   = -1
    let mutable month  = -1
    let mutable day    = -1
    let mutable hour   = -1
    let mutable minute = -1
    let mutable second = -1
    let dateTimeArray  = "xxxx-xx-xx xx:xx:xx.xxx".ToCharArray()
    let timeArray      = "xx:xx:xx.xxx".ToCharArray()
    let zeroChar       = int '0'

    // format the datetime into a date and a time with milliseconds
    let format (dateTime: DateTime) =

        if dateTime.Year <> year then
            year <- dateTime.Year
            dateTimeArray.[0] <- char (zeroChar + year / 1000)
            dateTimeArray.[1] <- char (zeroChar + (year % 1000) / 100)
            dateTimeArray.[2] <- char (zeroChar + (year % 100) / 10)
            dateTimeArray.[3] <- char (zeroChar + (year % 10))

        if dateTime.Month <> month then
            month <- dateTime.Month
            dateTimeArray.[5] <- char (zeroChar + month / 10)
            dateTimeArray.[6] <- char (zeroChar + month % 10)

        if dateTime.Day <> day then
            day <- dateTime.Day
            dateTimeArray.[8] <- char (zeroChar + day / 10)
            dateTimeArray.[9] <- char (zeroChar + day % 10)

        if dateTime.Hour <> hour then
            hour <- dateTime.Hour
            dateTimeArray.[11] <- char (zeroChar + hour / 10)
            dateTimeArray.[12] <- char (zeroChar + hour % 10)

        if dateTime.Minute <> minute then
            minute <- dateTime.Minute
            dateTimeArray.[14] <- char (zeroChar + minute / 10)
            dateTimeArray.[15] <- char (zeroChar + minute % 10)

        if dateTime.Second <> second then
            second <- dateTime.Second
            dateTimeArray.[17] <- char (zeroChar + second / 10)
            dateTimeArray.[18] <- char (zeroChar + second % 10)

        let ms = dateTime.Millisecond
        dateTimeArray.[20] <- char (zeroChar + ms / 100)
        dateTimeArray.[21] <- char (zeroChar + (ms % 100) / 10)
        dateTimeArray.[22] <- char (zeroChar + ms % 10)

        new string(dateTimeArray)

The idea is to build date time + millisecond timestamp as fast as possible.

But sometimes, and not always, I get this output:

2021-06-01 xx:xx:53.648

And the failure is always on the hours / minutes, but sometimes it works fine and sometimes it doesn't. and I don't see anything wrong with the tests when building the string, but it looks like hour and minutes fail even the first test since there is the placeholder 'x' in place.

It may be one of these super simple things that require another set of eyes to see it :)

yes, it's used in a bunch of async / parallel calls; I guess it would be conceivable that one call has an equality test passing while another one just set the value and hasn't set the chars yet, but then the problem would happen once and then the chars would be set after that — Thomas, Jun 01 '21 at 13:05
@Thomas create formatter per thread. Otherwise you have unpredictable results even if you don't observe 'xx'. E.g. hour might be modified by thread which just started formatting and it will affect the thread that creates a new string at the same time. — Sergey Berezovskiy, Jun 01 '21 at 13:09
wasn't there a compiler mechanism in C# to request that fields would be per thread? I wonder if there is a F# equivalent. I think there was some attribute for that — Thomas, Jun 01 '21 at 13:14
Well, if you're claiming that it happens intermittently, not just on the first couple passes, then I'm afraid we'll need a repro. — Fyodor Soikin, Jun 01 '21 at 13:31
there are 2 failures I have seen: the 'x' remaining and the time just being wrong. I could maybe do a loop that creates strings and parses them to make sure they're correct and run that in parallel to try to trigger the issue — Thomas, Jun 01 '21 at 13:34
@FyodorSoikin here is the repro https://pastebin.com/QxLjkXJ3 — Thomas, Jun 01 '21 at 14:11
I've a jupyter notebook too, but SO won't let me post a wetransfer link — Thomas, Jun 01 '21 at 14:13

Bent Tranberg · Accepted Answer · 2021-06-01T19:59:53.313

It fails because the mutables and dateTimeArray in the module is being walked all over from different threads. This is not thread safe code.

I posted some comments that I've now deleted, because I didn't look at the code long enough to understand the intention. The intention is obviously to optimize, but it fails. Simplifying the function will actually improve performance. The extra logic and extra variables didn't help, any of them. This code below is still faster.

I somewhat doubt that thread local storage can help the original code to beat this code, because I don't think it's in that logic any performance benefit can be found. I think the benefit over DateTime.ToString is in what's left in this simplified code:

let dateTimeArray = "xxxx-xx-xx xx:xx:xx.xxx".ToCharArray()
let [<Literal>] zeroChar = 48 // '0'

let format (dateTime: DateTime) =

    let dateTimeArray = Array.copy dateTimeArray

    dateTimeArray.[0] <- char (zeroChar + dateTime.Year / 1000)
    dateTimeArray.[1] <- char (zeroChar + (dateTime.Year % 1000) / 100)
    dateTimeArray.[2] <- char (zeroChar + (dateTime.Year % 100) / 10)
    dateTimeArray.[3] <- char (zeroChar + (dateTime.Year % 10))

    dateTimeArray.[5] <- char (zeroChar + dateTime.Month / 10)
    dateTimeArray.[6] <- char (zeroChar + dateTime.Month % 10)

    dateTimeArray.[8] <- char (zeroChar + dateTime.Day / 10)
    dateTimeArray.[9] <- char (zeroChar + dateTime.Day % 10)

    dateTimeArray.[11] <- char (zeroChar + dateTime.Hour / 10)
    dateTimeArray.[12] <- char (zeroChar + dateTime.Hour % 10)

    dateTimeArray.[14] <- char (zeroChar + dateTime.Minute / 10)
    dateTimeArray.[15] <- char (zeroChar + dateTime.Minute % 10)

    dateTimeArray.[17] <- char (zeroChar + dateTime.Second / 10)
    dateTimeArray.[18] <- char (zeroChar + dateTime.Second % 10)

    dateTimeArray.[20] <- char (zeroChar + dateTime.Millisecond / 100)
    dateTimeArray.[21] <- char (zeroChar + (dateTime.Millisecond % 100) / 10)
    dateTimeArray.[22] <- char (zeroChar + dateTime.Millisecond % 10)

    new string(dateTimeArray)

Reading properties of dateTime multiple times does not slow down the function. Reading a property once, e.g. reading dateTime.Year once into a local value and then use it in four places, will actually make the function slower.

Looks like this will shave off some more time, and the outer dateTimeArray isn't needed any more:

let dateTimeArray: char[] =
    [|
        char (zeroChar + dateTime.Year / 1000)
        char (zeroChar + (dateTime.Year % 1000) / 100)
        char (zeroChar + (dateTime.Year % 100) / 10)
        char (zeroChar + (dateTime.Year % 10))
        '-'
        char (zeroChar + dateTime.Month / 10)
        char (zeroChar + dateTime.Month % 10)
        '-'
        char (zeroChar + dateTime.Day / 10)
        char (zeroChar + dateTime.Day % 10)
        ' '
        char (zeroChar + dateTime.Hour / 10)
        char (zeroChar + dateTime.Hour % 10)
        ':'
        char (zeroChar + dateTime.Minute / 10)
        char (zeroChar + dateTime.Minute % 10)
        ':'
        char (zeroChar + dateTime.Second / 10)
        char (zeroChar + dateTime.Second % 10)
        '.'
        char (zeroChar + dateTime.Millisecond / 100)
        char (zeroChar + (dateTime.Millisecond % 100) / 10)
        char (zeroChar + dateTime.Millisecond % 10)
    |]

And I have one more version. The use of Math.DivRem seems to shave off slightly more, but the lookup into array digits adds time, though it brings some elegance.

let format (dateTime: DateTime) =
    let monthHigh, monthLow = Math.DivRem (dateTime.Month, 10)
    let dayHigh, dayLow = Math.DivRem (dateTime.Day, 10)
    let hourHigh, hourLow = Math.DivRem (dateTime.Hour, 10)
    let minuteHigh, minuteLow = Math.DivRem (dateTime.Minute, 10)
    let secondHigh, secondLow = Math.DivRem (dateTime.Second, 10)
    let digit = [| '0'; '1'; '2'; '3'; '4'; '5'; '6'; '7'; '8'; '9' |]
    [|
        digit.[dateTime.Year / 1000]
        digit.[(dateTime.Year % 1000) / 100]
        digit.[(dateTime.Year % 100) / 10]
        digit.[dateTime.Year % 10]
        '-'
        digit.[monthHigh]
        digit.[monthLow]
        '-'
        digit.[dayHigh]
        digit.[dayLow]
        ' '
        digit.[hourHigh]
        digit.[hourLow]
        ':'
        digit.[minuteHigh]
        digit.[minuteLow]
        ':'
        digit.[secondHigh]
        digit.[secondLow]
        '.'
        digit.[dateTime.Millisecond / 100]
        digit.[(dateTime.Millisecond % 100) / 10]
        digit.[dateTime.Millisecond % 10]
    |] |> (fun a -> new String(a))

Thanks for looking closely into this. The code was originally built to timestamp a lot of data coming from a stream; while it was clearly not thread safe, I still don't understand the issue where the 'x' characters were printed multiple times. I could understand one time where one call sets the variable on the test while another code passes the test before the x is overwritten, but I don't understand how it could happen several times. — Thomas, Jun 01 '21 at 19:57
One point I don't understand is this: "Reading a property once, [...] into a local value and then use it in four places, will actually make the function slower." I have no clue how the dotnet compiler works, but, coming originally from the ASM/C world, I can't understand how that would be possible since you'd load up the value in a register and use it multiple time from there, especially since the use of that value is very local and the code involved doesn't juggle between a lot of values. How can it be slower? — Thomas, Jun 01 '21 at 20:01
I don't know why it's slower, but a guess might be that more instructions than needed are generated, and not optimized away. And perhaps the compiler can optimize several accesses to these properties. — Bent Tranberg, Jun 01 '21 at 20:04
When mutable data is accessed unsafely from several threads, all rules go out the window. There's no point trying to make sense of what you see. You get these really weird magical effects. Modifications not taking effect is just a small part of the chaos that ensues. It has to do with each thread holding values in registers temporarily, and not expecting other threads to tamper with the same memory, and this is only part of the complexity. That 'x' could be in the memory, or in some thread's cache or register or something, while another thread has actually updated the memory. — Bent Tranberg, Jun 01 '21 at 20:26
Slightly off topic: I have sometimes used a bool to signal something from one thread to another. This doesn't work reliably right out of the box, because of these caching effects. You can actually get fooled, and see trouble only after you compile for release, or even sporadically only after deploying. But my point is; there are ways around it - but I don't have a good overview of them. Last time I did something like that, I believe I used a .NET call to somehow mark the bool as volatile. F# has a volatile keyword, but not sure if that can do the trick - possibly reserved for future use. — Bent Tranberg, Jun 01 '21 at 20:47
https://stackoverflow.com/questions/44692780/c-sharp-volatile-variable-memory-fences-vs-caching — Bent Tranberg, Jun 02 '21 at 11:06

Can't find why this datetime test fails, in F#

1 Answers1