Proper use of static keyword
Recently I found a funny bug in our code and I wanted to share some insights on it so you won’t do the same mistakes.
Let’s assume we have a function that produces a lot of output and it can run from multiple threads. I wrote a simple program to demonstrate it:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 | #include <iostream> #include <thread> #include <chrono> #include <atomic> class MyClass { public: MyClass(const std::string& name, std::atomic<bool>& stopCondition) : m_name(name) , m_stopCondition(stopCondition) {} void doSomething() { while (m_stopCondition.load(std::memory_order_acquire)) { std::cout << m_name << ": I am a log message..." << std::endl; std::this_thread::sleep_for(std::chrono::milliseconds(100)); } } private: std::string m_name; std::atomic<bool>& m_stopCondition; }; int main() { std::atomic<bool> stopCondition(true); MyClass a("Class A", stopCondition), b("Class B", stopCondition); std::thread w1 = std::thread([&a]() { a.doSomething(); }); std::thread w2 = std::thread([&b]() { b.doSomething(); }); std::this_thread::sleep_for(std::chrono::seconds(1)); stopCondition.store(false, std::memory_order_release); w1.join(); w2.join(); return 0; } |
The sharpest eyes can see that writing to the standard output is not thread safe so running this program will produce bad output:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 | [20:49 alexander ~/Projects ]$ g++ -std=c++0x threads.cpp -lpthread [20:49 alexander ~/Projects ]$ ./a.out Class B: I am a log message... Class A: I am a log message... Class BClass A: I am a log message...: I am a log message... Class B: I am a log message... Class A: I am a log message... Class B: I am a log message... Class A: I am a log message... Class B: I am a log message... Class A: I am a log message... Class B: I am a log message... Class A: I am a log message... Class BClass A: I am a log message...: I am a log message... Class BClass A: I am a log message...: I am a log message... Class A: I am a log message... Class B: I am a log message... Class A: I am a log message... Class B: I am a log message... |
The simple solution to fix it is using a mutex that will be shared between all the instances and will make sure the output is synchronized. In order to do that, we’ll simply create a static function variable and use it as our guard:
1 2 3 4 5 6 7 8 9 10 11 12 | void doSomething() { static std::mutex s_lock; while (m_stopCondition.load(std::memory_order_acquire)) { std::unique_lock<std::mutex> guard(s_lock); std::cout << m_name << ": I am a log message..." << std::endl; guard.unlock(); std::this_thread::sleep_for(std::chrono::milliseconds(100)); } } |
And the output is much better:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 | [20:50 alexander ~/Projects ]$ g++ -std=c++0x threads.cpp -lpthread [20:50 alexander ~/Projects ]$ ./a.out Class B: I am a log message... Class A: I am a log message... Class B: I am a log message... Class A: I am a log message... Class A: I am a log message... Class B: I am a log message... Class B: I am a log message... Class A: I am a log message... Class B: I am a log message... Class A: I am a log message... Class B: I am a log message... Class A: I am a log message... Class A: I am a log message... Class B: I am a log message... Class B: I am a log message... Class A: I am a log message... Class A: I am a log message... Class B: I am a log message... Class A: I am a log message... Class B: I am a log message... |
So far so good. Now we noticed that the logs are flooded with the same message so we wanted to suppress the output and make sure the message will be shown only once a second. What I found in the code was this:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 | void doSomething() { static std::mutex s_lock; static uint64_t counter = 0; while (m_stopCondition.load(std::memory_order_acquire)) { if (++counter % 10 == 0) { std::lock_guard<std::mutex> guard(s_lock); std::cout << m_name << ": I am a log message..." << std::endl; } std::this_thread::sleep_for(std::chrono::milliseconds(10)); } } |
Looks like the results are not as expected:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 | [20:51 alexander ~/Projects ]$ g++ -std=c++0x threads.cpp -lpthread [20:51 alexander ~/Projects ]$ ./a.out Class A: I am a log message... Class A: I am a log message... Class A: I am a log message... Class A: I am a log message... Class A: I am a log message... Class A: I am a log message... Class A: I am a log message... Class A: I am a log message... Class A: I am a log message... Class A: I am a log message... Class A: I am a log message... Class A: I am a log message... Class A: I am a log message... Class B: I am a log message... Class B: I am a log message... Class A: I am a log message... Class B: I am a log message... Class A: I am a log message... |
What happened ? We can identify two problems here.
- Thread safety – counter is a variable of type uint64_t and it’s not atomic so when multiple threads access it, it’s value can be undefined.
- Not the required behavior – we wanted to suppress the messages of each class independently but using counter as a static variable breaks this because it’s value is shared between all the instances of MyClass.
In this case, the proper case would be using counter as a class member instead of static variable:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 | class MyClass { public: MyClass(const std::string& name, std::atomic<bool>& stopCondition) : m_name(name) , m_stopCondition(stopCondition) , m_counter(0) {} void doSomething() { static std::mutex s_lock; m_counter = 0; while (m_stopCondition.load(std::memory_order_acquire)) { if (++m_counter % 10 == 0) { std::lock_guard<std::mutex> guard(s_lock); std::cout << m_name << "I am a log message..." << std::endl; } std::this_thread::sleep_for(std::chrono::milliseconds(10)); } } private: std::string m_name; std::atomic<bool>& m_stopCondition; uint64_t m_counter; }; |
And now the output looks much better:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 | [20:52 alexander ~/Projects ]$ g++ -std=c++0x threads.cpp -lpthread [20:52 alexander ~/Projects ]$ ./a.out Class B: I am a log message... Class A: I am a log message... Class B: I am a log message... Class A: I am a log message... Class A: I am a log message... Class B: I am a log message... Class B: I am a log message... Class A: I am a log message... Class A: I am a log message... Class B: I am a log message... Class B: I am a log message... Class A: I am a log message... Class B: I am a log message... Class A: I am a log message... Class A: I am a log message... Class B: I am a log message... Class B: I am a log message... Class A: I am a log message... |
Yes, in this example counter can be a local function variable and it will have the same effect. In the original bug the case was a bit different, doSomething was a scheduled function tat was called from an event-loop once a second so the function local variables can’t help us. In this example I tried to make the things simpler to get the point 🙂
Be aware when using static variables and class members, it can break your OOP design and make stuff more Singleton like.
– Alexander