MySQL Bugs: #91487: performance of fprintf is questionable

Bug #91487	performance of fprintf is questionable - error logging improvable?
Submitted:	29 Jun 2018 9:19	Modified:	6 Jul 2018 7:38
Reporter:	Shane Bester (Platinum Quality Contributor)	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S5 (Performance)
Version:	5.7.22, 8.0.13	OS:	Windows
Assigned to:		CPU Architecture:	Any

Description:
I found many small writes occurring on disk.  It seems the culprit is messages getting written to the error log, that are calling low-level WriteFile operations to write 1 byte at a time to disk...

E.g. output of procmon shows clearly:

11:09:21.6528123	mysqld-debug.exe	100864	WriteFile	E:\gr\n1\3306\sandboxdata\n1.err	SUCCESS	Offset: 82 746 002, Length: 1, Priority: Normal
11:09:21.6532287	mysqld-debug.exe	100864	QueryStandardInformationFile	E:\gr\n1\3306\sandboxdata\n1.err	SUCCESS	AllocationSize: 82 747 392, EndOfFile: 82 746 003, NumberOfLinks: 1, DeletePending: False, Directory: False
11:09:43.3724879	mysqld-debug.exe	100864	WriteFile	E:\gr\n1\3306\sandboxdata\n1.err	SUCCESS	Offset: 82 746 003, Length: 1, Priority: Normal
11:09:43.3725310	mysqld-debug.exe	100864	QueryStandardInformationFile	E:\gr\n1\3306\sandboxdata\n1.err	SUCCESS	AllocationSize: 82 747 392, EndOfFile: 82 746 004, NumberOfLinks: 1, DeletePending: False, Directory: False
11:09:43.3725643	mysqld-debug.exe	100864	WriteFile	E:\gr\n1\3306\sandboxdata\n1.err	SUCCESS	Offset: 82 746 004, Length: 1, Priority: Normal
11:09:43.3725830	mysqld-debug.exe	100864	QueryStandardInformationFile	E:\gr\n1\3306\sandboxdata\n1.err	SUCCESS	AllocationSize: 82 747 392, EndOfFile: 82 746 005, NumberOfLinks: 1, DeletePending: False, Directory: False
11:09:43.3726083	mysqld-debug.exe	100864	WriteFile	E:\gr\n1\3306\sandboxdata\n1.err	SUCCESS	Offset: 82 746 005, Length: 1, Priority: Normal
11:09:43.3726248	mysqld-debug.exe	100864	QueryStandardInformationFile	E:\gr\n1\3306\sandboxdata\n1.err	SUCCESS	AllocationSize: 82 747 392, EndOfFile: 82 746 006, NumberOfLinks: 1, DeletePending: False, Directory: False
11:09:43.3726489	mysqld-debug.exe	100864	WriteFile	E:\gr\n1\3306\sandboxdata\n1.err	SUCCESS	Offset: 82 746 006, Length: 1, Priority: Normal
11:09:43.3726645	mysqld-debug.exe	100864	QueryStandardInformationFile	E:\gr\n1\3306\sandboxdata\n1.err	SUCCESS	AllocationSize: 82 747 392, EndOfFile: 82 746 007, NumberOfLinks: 1, DeletePending: False, Directory: False
11:09:43.3726883	mysqld-debug.exe	100864	WriteFile	E:\gr\n1\3306\sandboxdata\n1.err	SUCCESS	Offset: 82 746 007, Length: 1, Priority: Normal

This is completely inefficient!!  The call stack leading up to it:

<cut>
ucrtbased.dll!__stdio_common_vfprintf()	Unknown
mysqld-debug.exe!fprintf(_iobuf * const _Stream=0x000007fedd4389f0, const char * const _Format=0x0000000140a9f078, ...) Line 835	C++
mysqld-debug.exe!print_buffer_to_file(loglevel level=INFORMATION_LEVEL, const char * buffer=0x0000000000157080, unsigned __int64 length=26) Line 2100	C++
mysqld-debug.exe!error_log_print(loglevel level=INFORMATION_LEVEL, const char * format=0x00000001411d55c0, char * args=0x0000000000157588) Line 2122	C++
mysqld-debug.exe!sql_print_information(const char * format=0x00000001411d55c0, ...) Line 2168	C++
<cut>

It looks like fprintf calls introduce too much overhead here.

How to repeat:
When many lines are written to error log (any message), monitor the process disk i/o count and bytes written.  you will see many tiny 1 byte writes.

Suggested fix:
Have not benchmarked it,  but i would think using snprintf to construct the message in memory first, then a simple fputs other non-formatted function call to write the error log is better ??

aka, avoid using fprintf totally.

I do not know how to get "procmon" equivalent outputs on Linux to check there...

it totally doesn't matter the content,  but in my case server error log was getting loads of these during a testcase, which lead me to investigate further:

2018-06-29T08:19:14.324510Z 51 [ERROR] Plugin group_replication reported: 'Table t0014 does not have any PRIMARY KEY. This is not compatible with Group Replication'
2018-06-29T08:19:14.325510Z 49 [ERROR] Plugin group_replication reported: 'Table t0030 does not have any PRIMARY KEY. This is not compatible with Group Replication'
2018-06-29T08:19:14.327510Z 48 [ERROR] Plugin group_replication reported: 'Table t0019 does not have any PRIMARY KEY. This is not compatible with Group Replication'
2018-06-29T08:19:14.328511Z 50 [ERROR] Plugin group_replication reported: 'Table t0039 does not have any PRIMARY KEY. This is not compatible with Group Replication'
2018-06-29T08:19:14.331011Z 51 [ERROR] Plugin group_replication reported: 'Table t0039 does not have any PRIMARY KEY. This is not compatible with Group Replication'
2018-06-29T08:19:14.331511Z 47 [ERROR] Plugin group_replication reported: 'Table t0030 does not have any PRIMARY KEY. This is not compatible with Group Replication'
2018-06-29T08:19:14.332011Z 49 [ERROR] Plugin group_replication reported: 'Table t0044 does not have any PRIMARY KEY. This is not compatible with Group Replication'
2018-06-29T08:19:14.332511Z 48 [ERROR] Plugin group_replication reported: 'Table t0009 does not have any PRIMARY KEY. This is not compatible with Group Replication'

Hello Shane,

Thank you for the report!

####
16	mysqld.exe	print_buffer_to_file + 0x2cc, g:\ade\build\sb_0-27500212-1520173462.4\mysql-5.7.22\sql\log.cc(2098)	0x13fcee5ac	D:\ushastry\MySQL\mysql-5.7.22-winx64\bin\mysqld.exe
17	mysqld.exe	error_log_print + 0x49, g:\ade\build\sb_0-27500212-1520173462.4\mysql-5.7.22\sql\log.cc(2118)	0x13fceb709	D:\ushastry\MySQL\mysql-5.7.22-winx64\bin\mysqld.exe
18	mysqld.exe	sql_print_information + 0x2a, g:\ade\build\sb_0-27500212-1520173462.4\mysql-5.7.22\sql\log.cc(2167)	0x13fcef0aa	D:\ushastry\MySQL\mysql-5.7.22-winx64\bin\mysqld.exe

--
7:46:10.3915328 AM	mysqld.exe	292	QueryStandardInformationFile	D:\ushastry\MySQL\mysql-5.7.22-winx64\data\error.log	SUCCESS	AllocationSize: 32,768, EndOfFile: 32,643, NumberOfLinks: 1, DeletePending: False, Directory: False
7:46:10.3915517 AM	mysqld.exe	292	WriteFile	D:\ushastry\MySQL\mysql-5.7.22-winx64\data\error.log	SUCCESS	Offset: 32,643, Length: 1
7:46:10.3915732 AM	mysqld.exe	292	QueryStandardInformationFile	D:\ushastry\MySQL\mysql-5.7.22-winx64\data\error.log	SUCCESS	AllocationSize: 32,768, EndOfFile: 32,644, NumberOfLinks: 1, DeletePending: False, Directory: False
7:46:10.3915920 AM	mysqld.exe	292	WriteFile	D:\ushastry\MySQL\mysql-5.7.22-winx64\data\error.log	SUCCESS	Offset: 32,644, Length: 1
7:46:10.3916136 AM	mysqld.exe	292	QueryStandardInformationFile	D:\ushastry\MySQL\mysql-5.7.22-winx64\data\error.log	SUCCESS	AllocationSize: 32,768, EndOfFile: 32,645, NumberOfLinks: 1, DeletePending: False, Directory: False
7:46:10.3916324 AM	mysqld.exe	292	WriteFile	D:\ushastry\MySQL\mysql-5.7.22-winx64\data\error.log	SUCCESS	Offset: 32,645, Length: 1
7:46:10.3916540 AM	mysqld.exe	292	QueryStandardInformationFile	D:\ushastry\MySQL\mysql-5.7.22-winx64\data\error.log	SUCCESS	AllocationSize: 32,768, EndOfFile: 32,646, NumberOfLinks: 1, DeletePending: False, Directory: False
7:46:10.3916724 AM	mysqld.exe	292	WriteFile	D:\ushastry\MySQL\mysql-5.7.22-winx64\data\error.log	SUCCESS	Offset: 32,646, Length: 2
7:46:10.3917008 AM	mysqld.exe	292	QueryStandardInformationFile	D:\ushastry\MySQL\mysql-5.7.22-winx64\data\error.log	SUCCESS	AllocationSize: 32,768, EndOfFile: 32,648, NumberOfLinks: 1, DeletePending: False, Directory: False
7:46:10.3917200 AM	mysqld.exe	292	WriteFile	D:\ushastry\MySQL\mysql-5.7.22-winx64\data\error.log	SUCCESS	Offset: 32,648, Length: 1
7:46:10.3917426 AM	mysqld.exe	292	QueryStandardInformationFile	D:\ushastry\MySQL\mysql-5.7.22-winx64\data\error.log	SUCCESS	AllocationSize: 32,768, EndOfFile: 32,649, NumberOfLinks: 1, DeletePending: False, Directory: False
7:46:10.3917618 AM	mysqld.exe	292	WriteFile	D:\ushastry\MySQL\mysql-5.7.22-winx64\data\error.log	SUCCESS	Offset: 32,649, Length: 1
7:46:10.3917833 AM	mysqld.exe	292	QueryStandardInformationFile	D:\ushastry\MySQL\mysql-5.7.22-winx64\data\error.log	SUCCESS	AllocationSize: 32,768, EndOfFile: 32,650, NumberOfLinks: 1, DeletePending: False, Directory: False
7:46:10.3918025 AM	mysqld.exe	292	WriteFile	D:\ushastry\MySQL\mysql-5.7.22-winx64\data\error.log	SUCCESS	Offset: 32,650, Length: 1
7:46:10.3918240 AM	mysqld.exe	292	QueryStandardInformationFile	D:\ushastry\MySQL\mysql-5.7.22-winx64\data\error.log	SUCCESS	AllocationSize: 32,768, EndOfFile: 32,651, NumberOfLinks: 1, DeletePending: False, Directory: False
7:46:10.3918429 AM	mysqld.exe	292	WriteFile	D:\ushastry\MySQL\mysql-5.7.22-winx64\data\error.log	SUCCESS	Offset: 32,651, Length: 1
7:46:10.3918644 AM	mysqld.exe	292	QueryStandardInformationFile	D:\ushastry\MySQL\mysql-5.7.22-winx64\data\error.log	SUCCESS	AllocationSize: 32,768, EndOfFile: 32,652, NumberOfLinks: 1, DeletePending: False, Directory: False
7:46:10.3918832 AM	mysqld.exe	292	WriteFile	D:\ushastry\MySQL\mysql-5.7.22-winx64\data\error.log	SUCCESS	Offset: 32,652, Length: 1

Regards,
Umesh

yeah so i'd prefer: construct message in memory, then a single write function puts it on disk.  not 1 write for each byte....

Seen the same phenomenon on 8.0.  Just to clarify, this is not really an issue unless you have huge amounts of log lines getting written to the error log, in which case you should probably address the underlying problem or filter them out as per new functionality available to do so.    

See:
26	ucrtbased.dll	_stdio_common_vfprintf + 0x3b	0x7fedd9b5ecb	C:\Windows\System32\ucrtbased.dll
27	mysqld-debug.exe	fprintf + 0x81, c:\program files (x86)\windows kits\10\include\10.0.10240.0\ucrt\stdio.h(835)	0x13f7eea11	E:\git\mysql-trunk\bld\runtime_output_directory\Debug\mysqld-debug.exe
28	mysqld-debug.exe	log_write_errstream + 0xba, e:\git\mysql-trunk\sql\log.cc(1878)	0x13f8fb92a	E:\git\mysql-trunk\bld\runtime_output_directory\Debug\mysqld-debug.exe
29	mysqld-debug.exe	log_sink_trad + 0x61c, e:\git\mysql-trunk\components\mysql_server\log_builtins.cc(1309)	0x142dd5b5c	E:\git\mysql-trunk\bld\runtime_output_directory\Debug\mysqld-debug.exe
30	mysqld-debug.exe	log_line_submit + 0xa53, e:\git\mysql-trunk\components\mysql_server\log_builtins.cc(1733)	0x142dd3d93	E:\git\mysql-trunk\bld\runtime_output_directory\Debug\mysqld-debug.exe
31	mysqld-debug.exe	log_sink_buffer_flush + 0x35d, e:\git\mysql-trunk\components\mysql_server\log_builtins.cc(1507)	0x142dd05fd	E:\git\mysql-trunk\bld\runtime_output_directory\Debug\mysqld-debug.exe
32	mysqld-debug.exe	flush_error_log_messages + 0x1f, e:\git\mysql-trunk\sql\log.cc(1749)	0x13f8fb85f	E:\git\mysql-trunk\bld\runtime_output_directory\Debug\mysqld-debug.exe
33	mysqld-debug.exe	win_main + 0x37b9, e:\git\mysql-trunk\sql\mysqld.cc(6529)	0x13f7cb1b9	E:\git\mysql-trunk\bld\runtime_output_directory\Debug\mysqld-debug.exe
34	mysqld-debug.exe	mysql_service + 0xc7, e:\git\mysql-trunk\sql\mysqld.cc(6719)	0x13f7cbda7	E:\git\mysql-trunk\bld\runtime_output_directory\Debug\mysqld-debug.exe
35	mysqld-debug.exe	mysqld_main + 0x9f5, e:\git\mysql-trunk\sql\mysqld.cc(6936)	0x13f7ccc25	E:\git\mysql-trunk\bld\runtime_output_directory\Debug\mysqld-debug.exe
36	mysqld-debug.exe	main + 0x2f, e:\git\mysql-trunk\sql\main.cc(30)	0x13f7a81ef	E:\git\mysql-trunk\bld\runtime_output_directory\Debug\mysqld-debug.exe
37	mysqld-debug.exe	invoke_main + 0x34, f:\dd\vctools\crt\vcstartup\src\startup\exe_common.inl(64)	0x142f04284	E:\git\mysql-trunk\bld\runtime_output_directory\Debug\mysqld-debug.exe
38	mysqld-debug.exe	__scrt_common_main_seh + 0x127, f:\dd\vctools\crt\vcstartup\src\startup\exe_common.inl(246)	0x142f04197	E:\git\mysql-trunk\bld\runtime_output_directory\Debug\mysqld-debug.exe
39	mysqld-debug.exe	__scrt_common_main + 0xe, f:\dd\vctools\crt\vcstartup\src\startup\exe_common.inl(295)	0x142f0405e	E:\git\mysql-trunk\bld\runtime_output_directory\Debug\mysqld-debug.exe
40	mysqld-debug.exe	mainCRTStartup + 0x9, f:\dd\vctools\crt\vcstartup\src\startup\exe_main.cpp(16)	0x142f04299	E:\git\mysql-trunk\bld\runtime_output_directory\Debug\mysqld-debug.exe

06:32:48.1353173	mysqld-debug.exe	9116	FASTIO_WRITE	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Offset: 24 625, Length: 1
06:32:48.1353297	mysqld-debug.exe	9116	FASTIO_QUERY_INFORMATION	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Type: QueryStandardInformationFile, AllocationSize: 32 768, EndOfFile: 24 626, NumberOfLinks: 1, DeletePending: False, Directory: False
06:32:48.1353411	mysqld-debug.exe	9116	FASTIO_WRITE	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Offset: 24 626, Length: 1
06:32:48.1353537	mysqld-debug.exe	9116	FASTIO_QUERY_INFORMATION	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Type: QueryStandardInformationFile, AllocationSize: 32 768, EndOfFile: 24 627, NumberOfLinks: 1, DeletePending: False, Directory: False
06:32:48.1353649	mysqld-debug.exe	9116	FASTIO_WRITE	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Offset: 24 627, Length: 1
06:32:48.1353775	mysqld-debug.exe	9116	FASTIO_QUERY_INFORMATION	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Type: QueryStandardInformationFile, AllocationSize: 32 768, EndOfFile: 24 628, NumberOfLinks: 1, DeletePending: False, Directory: False
06:32:48.1353886	mysqld-debug.exe	9116	FASTIO_WRITE	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Offset: 24 628, Length: 1
06:32:48.1354016	mysqld-debug.exe	9116	FASTIO_QUERY_INFORMATION	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Type: QueryStandardInformationFile, AllocationSize: 32 768, EndOfFile: 24 629, NumberOfLinks: 1, DeletePending: False, Directory: False
06:32:48.1354127	mysqld-debug.exe	9116	FASTIO_WRITE	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Offset: 24 629, Length: 1
06:32:48.1354253	mysqld-debug.exe	9116	FASTIO_QUERY_INFORMATION	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Type: QueryStandardInformationFile, AllocationSize: 32 768, EndOfFile: 24 630, NumberOfLinks: 1, DeletePending: False, Directory: False
06:32:48.1354365	mysqld-debug.exe	9116	FASTIO_WRITE	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Offset: 24 630, Length: 1
06:32:48.1354491	mysqld-debug.exe	9116	FASTIO_QUERY_INFORMATION	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Type: QueryStandardInformationFile, AllocationSize: 32 768, EndOfFile: 24 631, NumberOfLinks: 1, DeletePending: False, Directory: False
06:32:48.1354602	mysqld-debug.exe	9116	FASTIO_WRITE	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Offset: 24 631, Length: 1
06:32:48.1354732	mysqld-debug.exe	9116	FASTIO_QUERY_INFORMATION	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Type: QueryStandardInformationFile, AllocationSize: 32 768, EndOfFile: 24 632, NumberOfLinks: 1, DeletePending: False, Directory: False
06:32:48.1354843	mysqld-debug.exe	9116	FASTIO_WRITE	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Offset: 24 632, Length: 1
06:32:48.1354966	mysqld-debug.exe	9116	FASTIO_QUERY_INFORMATION	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Type: QueryStandardInformationFile, AllocationSize: 32 768, EndOfFile: 24 633, NumberOfLinks: 1, DeletePending: False, Directory: False
06:32:48.1355081	mysqld-debug.exe	9116	FASTIO_WRITE	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Offset: 24 633, Length: 1
06:32:48.1355204	mysqld-debug.exe	9116	FASTIO_QUERY_INFORMATION	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Type: QueryStandardInformationFile, AllocationSize: 32 768, EndOfFile: 24 634, NumberOfLinks: 1, DeletePending: False, Directory: False
06:32:48.1355318	mysqld-debug.exe	9116	FASTIO_WRITE	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Offset: 24 634, Length: 1
06:32:48.1355445	mysqld-debug.exe	9116	FASTIO_QUERY_INFORMATION	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Type: QueryStandardInformationFile, AllocationSize: 32 768, EndOfFile: 24 635, NumberOfLinks: 1, DeletePending: False, Directory: False
06:32:48.1355556	mysqld-debug.exe	9116	FASTIO_WRITE	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Offset: 24 635, Length: 1
06:32:48.1355683	mysqld-debug.exe	9116	FASTIO_QUERY_INFORMATION	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Type: QueryStandardInformationFile, AllocationSize: 32 768, EndOfFile: 24 636, NumberOfLinks: 1, DeletePending: False, Directory: False
06:32:48.1355797	mysqld-debug.exe	9116	FASTIO_WRITE	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Offset: 24 636, Length: 1
06:32:48.1355923	mysqld-debug.exe	9116	FASTIO_QUERY_INFORMATION	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Type: QueryStandardInformationFile, AllocationSize: 32 768, EndOfFile: 24 637, NumberOfLinks: 1, DeletePending: False, Directory: False
06:32:48.1356044	mysqld-debug.exe	9116	FASTIO_WRITE	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Offset: 24 637, Length: 1
06:32:48.1356170	mysqld-debug.exe	9116	FASTIO_QUERY_INFORMATION	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Type: QueryStandardInformationFile, AllocationSize: 32 768, EndOfFile: 24 638, NumberOfLinks: 1, DeletePending: False, Directory: False
06:32:48.1356281	mysqld-debug.exe	9116	FASTIO_WRITE	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Offset: 24 638, Length: 1
06:32:48.1356408	mysqld-debug.exe	9116	FASTIO_QUERY_INFORMATION	E:\git\mysql-trunk\bld\data\hello.err	SUCCESS	Type: QueryStandardInformationFile, AllocationSize: 32 768, EndOfFile: 24 639, NumberOfLinks: 1, DeletePending: False, Directory: False

Same thing on 8.0.19.  small 1 byte writes to the error log.

--
mysqld.exe	13492	QueryStandardInformationFile	C:\ade\mysql-commercial-8.0.19-winx64\data\err.log	SUCCESS	AllocationSize: 8 192, EndOfFile: 6 556, NumberOfLinks: 1, DeletePending: False, Directory: False	2020/04/24 5:56:32 PM	C:\ade\mysql-commercial-8.0.19-winx64\bin\mysqld.exe	S-1-5-21-1968755584-532765302-1913978381-1002	mysqld --log-error=err.log --net-read-timeout=1 --log-error-verbosity=3 --net-write-timeout=1 --wait-timeout=1	3944	16520
mysqld.exe	13492	WriteFile	C:\ade\mysql-commercial-8.0.19-winx64\data\err.log	SUCCESS	Offset: 6 556, Length: 1	2020/04/24 5:56:32 PM	C:\ade\mysql-commercial-8.0.19-winx64\bin\mysqld.exe	S-1-5-21-1968755584-532765302-1913978381-1002	mysqld --log-error=err.log --net-read-timeout=1 --log-error-verbosity=3 --net-write-timeout=1 --wait-timeout=1	3944	16520
...
--

I have an idea for a micro-benchmark to perform to measure the impact..  
I'll report back soon.

microbench to show fprintf poor performance on windows.

Attachment: bug91487_benchmark.cpp (text/plain), 2.85 KiB.

On my OBI laptop, windows 10 ,  the above microbench took:

fprintf elapsed time: 1988.39 seconds
fputs elapsed time  : 8.50302 seconds

fprintf is magnitudes slower.  Watching in TaskManager,  the fprintf is causing number of "I/O Writes" to increase crazily (since it is 1 byte per write).

I fixed my micro-benchmark by enabling buffering on stderr with this call:

setvbuf(stderr, NULL, _IOFBF, 4096);

After this,  the timings are more reasonable:

Successfully set _IOFBF for stderr
fprintf elapsed time: 14.7303 seconds
fputs elapsed time  : 13.1393 seconds

So,  MySQL needs to set buffering on stderr,  and flush that buffer after every line.

https://docs.microsoft.com/en-us/cpp/c-runtime-library/reference/setvbuf?view=vs-2019

I see in the MySQL Server,  Group Replication plugin debugging option enables the buffering by calling setvbuf, obviously for performance reasons,  as can be 
seen in the Patch for:

  WL#10200: Change GCS/XCOM to have dynamic debugging and tracing 

So I think MySQL error log could also enable this buffering;
Some customers have hundreds megabytes size error logs...

or a less intrusive fix,  is to snprintf the string to add the newline, then fputs it to stderr. (as I said in original post).

This performance report is specific to windows.

On linux there is no such problem, as I confirmed with strace it makes a single write() per error log line:

$ cat strace.txt |grep "write(2,"
774   20:58:19.817381 write(2, "2020-04-24T18:58:19.764722Z 0 [N"..., 157) = 157 <0.000031>
774   20:58:19.817474 write(2, "2020-04-24T18:58:19.764787Z 0 [N"..., 106) = 106 <0.000014>
774   20:58:19.817536 write(2, "2020-04-24T18:58:19.764931Z 0 [S"..., 145) = 145 <0.000012>
774   20:58:19.817591 write(2, "2020-04-24T18:58:19.816806Z 0 [N"..., 81) = 81 <0.000012>
774   20:58:19.822398 write(2, "2020-04-24T18:58:19.822340Z 0 [N"..., 90) = 90 <0.000043>
775   20:58:19.837410 write(2, "2020-04-24T18:58:19.837342Z 1 [S"..., 95) = 95 <0.000028>
775   20:58:19.837553 write(2, "2020-04-24T18:58:19.837502Z 1 [N"..., 79) = 79 <0.000018>
775   20:58:19.837907 write(2, "2020-04-24T18:58:19.837822Z 1 [N"..., 87) = 87 <0.000021>
775   20:58:19.838827 write(2, "2020-04-24T18:58:19.838766Z 1 [N"..., 103) = 103 <0.000027>
775   20:58:19.838997 write(2, "2020-04-24T18:58:19.838924Z 1 [N"..., 77) = 77 <0.000043>
775   20:58:19.839168 write(2, "2020-04-24T18:58:19.839100Z 1 [N"..., 121) = 121 <0.000018>
775   20:58:19.839321 write(2, "2020-04-24T18:58:19.839248Z 1 [N"..., 92) = 92 <0.000017>
775   20:58:19.846429 write(2, "2020-04-24T18:58:19.846364Z 1 [N"..., 77) = 77 <0.000019>
775   20:58:19.850165 write(2, "2020-04-24T18:58:19.850088Z 1 [N"..., 87) = 87 <0.000025>
775   20:58:19.856731 write(2, "2020-04-24T18:58:19.856675Z 1 [N"..., 83) = 83 <0.000016>
775   20:58:19.858589 write(2, "2020-04-24T18:58:19.858532Z 1 [N"..., 72) = 72 <0.000016>
775   20:58:19.874352 write(2, "2020-04-24T18:58:19.874223Z 1 [N"..., 95) = 95 <0.000023>
775   20:58:19.876553 write(2, "2020-04-24T18:58:19.876510Z 1 [N"..., 150) = 150 <0.000009>
775   20:58:19.911669 write(2, "2020-04-24T18:58:19.911547Z 1 [N"..., 98) = 98 <0.000014>
787   20:58:19.919469 write(2, "2020-04-24T18:58:19.919354Z 0 [N"..., 182) = 182 <0.000018>
775   20:58:19.923652 write(2, "2020-04-24T18:58:19.923581Z 1 [N"..., 102) = 102 <0.000016>
775   20:58:19.926342 write(2, "2020-04-24T18:58:19.926241Z 1 [N"..., 102) = 102 <0.000028>
775   20:58:20.006331 write(2, "2020-04-24T18:58:20.006225Z 1 [N"..., 87) = 87 <0.000019>
775   20:58:20.006472 write(2, "2020-04-24T18:58:20.006394Z 1 [N"..., 100) = 100 <0.000013>
775   20:58:20.006774 write(2, "2020-04-24T18:58:20.006693Z 1 [N"..., 102) = 102 <0.000011>