The notorious printf fix

Question

Through my experience I bumped into some odd behaviors when using printf (or any other std out logging ) for debugging .

Behavior 1 :

One common scenario Is when using printf in multithreaded applications in order to find why certain bug(s) are occurring, and using printf suddenly "fixed" the bug(s) (ofc printfs where agressivelly called, resulting in a huge output).

In this scenario I consider that printf adds some delays so there might be some low priority threads that don't get CPU, so I start looking in that direction.

Another direction I look after the miracle printf fix is on synchronization, because I speculate that calls to printf, although multithreaded , are synchronized behind by the system, so the different threads with printf get synchronized between themselves by waiting for each other to finish writing to the I/O buffer.

Q1 : Are my two suppositions regarding the first scenario correct ?

Q2 : Are there any other directions I should take into consideration when such a scenarios occurs ?

Behavior 2 :

This scenario very rarely happens , but when bumped into it will make even senior developers question themselves, and I would really appreciate an explanation regarding this.

It goes something like this :

• code doesn't work ... (clean, compile , run)
• code still doesn't work , so you add a printf to see why (clean, compile, run)
• code starts working fine .... you remove the previously added printf (clean, compile, run)
• the code works fine now !!!!!!!!!! (scratch head, stare in disbelief ).

In practice I used this approach more then once this approach to fix the CPU may pe pegged bug more then once when it occurred : Android "cpu may be pegged" bug .

It actually worked so well, that it became a known "fix" (and if it didn't work from the first try, you just repeat the process until it was gone).

Please note that the code was properly cleaned it was never the problem of linking with older compiled objects.

One of the most popular speculations is the fact that the compiled code is different , for unknown reasons (do compilers have some random according to lines of a certain file including whitespaces ? ).

Q3 : What can be the cause this behavior (I'm open to speculations as well) ? Can a compiler generate different assembly although the code is the same ?

Please note that the projects I'm talking about are quite large, with multiple static libraries, so these behaviors aren't replicable on small code snippets (although I've heard of scenario 2 happening on a single-file program as well).

Answer 1

Q1: You can tell if printf is synchronizing behind the scenes simply by looking for interleaved characters from two different printfs. If there's no interleaving, then printf is synchronizing. I expect this to be more likely to fix things than CPU hogging.

Q2: I would look for shared resources that aren't properly mutex protected.

Q3: Compilers may use random numbers during optimization. For example, if the compiler has 32 variables and 8 registers to put them in, it may "roll the dice" to determine which variables to put into registers. You can test this theory by disabling optimization. Without optimization, the output should be consistent. And you can test that theory by comparing binaries.

Answer 2

printf()'s thread safety is discussed in other questions e.g. here for linux and it's also noteworthy that any out-of-line function call can be expected to cause writes back to memory - to quote David Butenhoff

"In practice, most compilers will not try to keep register copies of global data across a call to an external function, because it's too hard to know whether the routine might somehow have access to the address of the data."

Either aspects can mean undefined behaviour caused by failing to use synchronisation instructions properly may be "masked" (with varying degrees of reliably depending on your architecture, the exact nature of the problem etc.) by calling printf().

As you say, the time spent calling printf can also affect the frequency with which race conditions turn out adversely.

Regarding re-compiling programs fixing bugs: firstly if the bug is intermittent in the first place, observing it before some change and not afterwards doesn't necessarily prove any causal relationship. There could be other factors such as less system load afterwards due to other factors such as anti-virus sweeps, backup schedules, other users etc.. Secondly, it's possible the executable might not be the same: the compiler might inject something like an incrementing version numbers or build timestamps or some other system data - a change in e.g. data length could have knock-on affects to the alignment of other data with lots of subtle consequences. It's also possible that your compiler's using address randomisation or some other techniques, which again could affect data alignment - in a way that might mask errors or change performance.