{"id":153,"date":"2022-05-08T18:00:37","date_gmt":"2022-05-08T16:00:37","guid":{"rendered":"https:\/\/mczerwonka.pl\/dev\/?p=153"},"modified":"2022-05-09T19:09:08","modified_gmt":"2022-05-09T17:09:08","slug":"why-avoid-sprintf","status":"publish","type":"post","link":"http:\/\/mczerwonka.pl\/dev\/why-avoid-sprintf\/","title":{"rendered":"Why avoid sprintf?"},"content":{"rendered":"\n

I was going to write about avoiding dynamic memory allocations during parallel execution, but when I was profiling a test code I found a bug in _free_dbg<\/code> which analysis consumed the time I had for this post, so I sidetracked a bit and I guess the initial topic will have to wait. <\/p>\n\n\n\n

But basically, dynamic allocations is not something you should do in your game code if performance matters, especially during parallel execution. If the above seems obvious this post probably is not for you. <\/p>\n\n\n\n

The other day I wanted to parallelize some serialization code, but the results in debug on Windows were mediocre at most. After some time I figured out that the main offender was _free_dbg<\/code>, even though I preallocated all the memory before the serialization. But lets start from the beginning.<\/p>\n\n\n\n

Imagine I have a class Foo, which represents my game object:<\/p>\n\n\n\n

struct Foo\n{\n    bool _Boolean;\n    float _FloatingPoint;\n    \/\/ ...\n};<\/code><\/pre><\/div>\n\n\n\n
I want to serialize those objects to a text buffer. Example implementation could look like this:<\/p>\n\n\n\n
int Foo::SerializeAsText(char* Buffer) const\n{\n    int chars = sprintf(Buffer, "%s", _Boolean ? "y" : "n");\n    chars += sprintf(Buffer + chars, "%.2f", _FloatingPoint);\n    return chars;\n}<\/code><\/pre><\/div>\n\n\n\n
Now I have my serialization in place and I want to profile it. To produce some reliable profiling data I need lots of objects, so I organized them into 1024 pages, every page containing 1024 objects.<\/p>\n\n\n\n
template<typename T, int PageCount = 1024, int PageSize = 1024>\nstruct Storage\n{\n    std::vector<std::vector<T>> _Pages;\n    \/\/ ...\n}<\/code><\/pre><\/div>\n\n\n\n
This setup produces  1024*1024=1048576  objects, which should be enough for profiling.<\/p>\n\n\n\n
Lets start from page by page serialization.<\/p>\n\n\n\n
template<typename T, int PageCount = 1024, int PageSize = 1024>\nstruct Storage\n{\n    template<typename int (T::* Serializer)(char*)>\n    void Serialize(char* Buffer)\n    {\n        for (const auto& Page : _Pages)\n            for (const auto& Object : Page)\n                Buffer += (Object.*Serializer)(Buffer);\n    }\n}<\/code><\/pre><\/div>\n\n\n\n
Page by page serialization takes 1015 milliseconds.<\/p>\n\n\n\n
\"\"<\/a>
Page by page serialization<\/figcaption><\/figure><\/div>\n\n\n\n
It is going to be my baseline. <\/p>\n\n\n\n
Lets do the same, but with parallel_for<\/code> iterating over pages of objects:<\/p>\n\n\n\n
template<typename T, int PageCount = 1024, int PageSize = 1024>\nstruct Storage\n{\n    void SerializeParallel(char* Buffer)\n    {\n        std::for_each(std::execution::par_unseq, _Pages.data(), _Pages.data() + PageCount, [&](const std::vector<T>& Page)\n            {\n                const int Index = &Page - _Pages.data();\n                char* LocalBuffer = Buffer + (Index * PageSize * T::SerializedSize);\n                for (const auto& Object : Page)\n                    LocalBuffer += (Object.*Serializer)(LocalBuffer);\n            });\n    }\n}<\/code><\/pre><\/div>\n\n\n\n
As you can see there’s no dynamic memory allocation happening. The buffer is preallocated before calling SerializeParallel<\/code>.<\/p>\n\n\n\n
Serializing pages in parallel takes 561 milliseconds.<\/p>\n\n\n\n
\"\"<\/a>
Parallel serialization<\/figcaption><\/figure><\/div>\n\n\n\n
Better than the baseline, but given I’m running this on Intel i7-8750H with 12 logical cores available, it’s far from what I expected. I’m going to take a closer look at what the program is actually doing when serializing in parallel.<\/p>\n\n\n\n
Starting from the thread utilization:<\/p>\n\n\n\n
\"\"<\/a>
Parallel serialization threads<\/figcaption><\/figure><\/div>\n\n\n\n
This doesn’t look good. There are lots of bubbles, where threads seem to idle or wait. I’m diving into call stacks to see where the bubbles come from just to find this:<\/p>\n\n\n\n
\"\"<\/a>
Call to _free_dbg<\/code> coming out of sprintf<\/code> implementation<\/figcaption><\/figure><\/div>\n\n\n\n
It looks that sprintf<\/code> under the hood calls a _free_dbg<\/code> which in turn triggers synchronization due to a lock. In the above screenshot the lock consumed 15 milliseconds! How many of those does the code hit? <\/p>\n\n\n\n
\"\"<\/a>
Locks in parallel serialization<\/figcaption><\/figure><\/div>\n\n\n\n
A lot. Lets look at the numbers:<\/p>\n\n\n\n
\"\"<\/a>
Time breakdown<\/figcaption><\/figure><\/div>\n\n\n\n
It seems that the serialization code spends 336 ms in locks (__acrt_lock<\/code>). It is 60% time of Foo::SerializeAsText<\/code>. Those numbers are crazy. <\/p>\n\n\n\n
Calls to _free_dbg<\/code> <\/em>mean that sprintf<\/code> <\/em>probably dynamically allocates memory in some cases. I don’t think it does in this situation, because there are no corresponding calls to malloc<\/code>. So why does it even show in the profiler? I guess because the caller assumes that calling free<\/code> with a nullptr<\/code> is a no-op (does nothing). But is it?<\/p>\n\n\n\n
Let’s look into the Windows SDK code (10.0.19041.0):<\/p>\n\n\n\n
\/\/ free.cpp\nextern "C" _CRT_HYBRIDPATCHABLE __declspec(noinline) void __cdecl free(void* const block)\n{\n    #ifdef _DEBUG\n    _free_dbg(block, _NORMAL_BLOCK);\n    #else\n    _free_base(block);\n    #endif\n}\n\n\/\/ debug_heap.cpp\nextern "C" __declspec(noinline) void __cdecl _free_dbg(void* const block, int const block_use)\n{\n    __acrt_lock(__acrt_heap_lock);\n    __try\n    {\n        int const actual_use{block_use == _UNKNOWN_BLOCK && block != nullptr\n            ? header_from_block(block)->_block_use\n            : block_use};\n\n        free_dbg_nolock(block, actual_use);\n    }\n    __finally\n    {\n        __acrt_unlock(__acrt_heap_lock);\n    }\n}\n\n\/\/ free_base.cpp\nextern "C" void __declspec(noinline) __cdecl _free_base(void* const block)\n{\n    if (block == nullptr)\n    {\n        return;\n    }\n\n    if (!HeapFree(select_heap(block), 0, block))\n    {\n        errno = __acrt_errno_from_os_error(GetLastError());\n    }\n}<\/code><\/pre><\/div>\n\n\n\n
Calling free(0)<\/code> in release actually is a no-op, but in debug it evaluates to a _free_dbg<\/code> which always locks, regardless of the argument. I’ve found a thread<\/a> on Visual Studio Developer Community, where someone raised it as an issue two years ago. Hopefully it’ll be fixed one day.<\/p>\n\n\n\n
\n\n\n\n
Getting back to the serialization – I am not going to fix sprintf<\/code> so that it doesn’t allocate memory, but there are bunch of alternatives out there. I’ve found nanoprintf<\/a> from Charles Nicholson to be a good replacement. It’s a single header, lightweight implementation and does not allocate memory. <\/p>\n\n\n\n
After replacing sprintf<\/code> with npf_snprintf<\/code> the profiler produces this output:<\/p>\n\n\n\n
\"\"<\/a>
Parallel serialize with nanoprintf instead of sprintf<\/figcaption><\/figure>\n\n\n\n
Thread utilization also looks nicer:<\/p>\n\n\n\n
\"\"<\/a>
Much better thread utilization with nanoprintf<\/figcaption><\/figure>\n\n\n\n
<\/p>\n\n\n\n
To sum this up – dynamic allocations in parallel execution are bad for performance as they lead to thread synchronization. You should strive to use preallocated memory and even then profile your code regularly to spot potential locks coming out of external libraries. <\/p>\n\n\n\n
You should also be careful about overusing printf-family functions in parallel code, as they might allocate memory and will always make a call to free<\/code> (even with a nullptr<\/code>) which currently triggers a lock on Windows when compiling in debug configuration. <\/p>\n","protected":false},"excerpt":{"rendered":"
I was going to write about avoiding dynamic memory allocations during parallel execution, but when I was profiling a test code I found a bug in _free_dbg which analysis consumed the time I had for this post, so I sidetracked a bit and I guess the initial topic will have to wait. But basically, dynamic allocations is not something you should do in your game code if performance matters, especially during parallel execution. If the above seems obvious this post probably is not for you. The other day I wanted to parallelize some serialization code, but the results in debug\u2026<\/p>\n","protected":false},"author":1,"featured_media":189,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":[],"categories":[23],"tags":[16,21,17,19,18,22,20],"blocksy_meta":{"styles_descriptor":{"styles":{"desktop":"","tablet":"","mobile":""},"google_fonts":[],"version":5}},"_links":{"self":[{"href":"http:\/\/mczerwonka.pl\/dev\/wp-json\/wp\/v2\/posts\/153"}],"collection":[{"href":"http:\/\/mczerwonka.pl\/dev\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"http:\/\/mczerwonka.pl\/dev\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"http:\/\/mczerwonka.pl\/dev\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"http:\/\/mczerwonka.pl\/dev\/wp-json\/wp\/v2\/comments?post=153"}],"version-history":[{"count":41,"href":"http:\/\/mczerwonka.pl\/dev\/wp-json\/wp\/v2\/posts\/153\/revisions"}],"predecessor-version":[{"id":212,"href":"http:\/\/mczerwonka.pl\/dev\/wp-json\/wp\/v2\/posts\/153\/revisions\/212"}],"wp:featuredmedia":[{"embeddable":true,"href":"http:\/\/mczerwonka.pl\/dev\/wp-json\/wp\/v2\/media\/189"}],"wp:attachment":[{"href":"http:\/\/mczerwonka.pl\/dev\/wp-json\/wp\/v2\/media?parent=153"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/mczerwonka.pl\/dev\/wp-json\/wp\/v2\/categories?post=153"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/mczerwonka.pl\/dev\/wp-json\/wp\/v2\/tags?post=153"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}