    <rss version="2.0" xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:sy="http://purl.org/rss/1.0/modules/syndication/" xmlns:admin="http://webns.net/mvcb/" xmlns:rdf="http://www.w3.org/1999/02/22-rdf-syntax-ns#" xmlns:content="http://purl.org/rss/1.0/modules/content/">
     <channel>
        <title>ACCU  :: Code Critique Competition 122</title>
        <link>https://members.accu.org/index.php/articles/2759</link>
        <description>Professionalism in Programming</description>
        <dc:language>en-us</dc:language> 
        <dc:creator>Administrator</dc:creator> 
        <admin:generatorAgent rdf:resource="http://www.xaraya.org" /> 
        <admin:errorReportsTo rdf:resource="mailto:webeditor@accu.org" />
       <sy:updatePeriod>hourly</sy:updatePeriod>
       <sy:updateFrequency>1</sy:updateFrequency>
       <docs>http://backend.userland.com/rss</docs>




<div class="xar-mod-head"><span class="xar-mod-title">Student Code Critiques from CVu journal. + CVu Journal Vol 32, #1 - March 2020</span></div>

<table border="0" cellpadding="1" cellspacing="0">
    <tbody>
    <tr>
        <td valign="top">
            Browse in :
       </td>
       <td valign="top">

                                            <a href="https://members.accu.org/index.php/articles/">All</a>

                     &gt;                         <a href="https://members.accu.org/index.php/articles/c184/">Journal Columns</a>

                     &gt;                         <a href="https://members.accu.org/index.php/articles/c183/">Code Critique</a>
<br />

                                            <a href="https://members.accu.org/index.php/articles/">All</a>

                     &gt;                         <a href="https://members.accu.org/index.php/articles/c76/">Journals</a>

                     &gt;                         <a href="https://members.accu.org/index.php/articles/c77/">CVu</a>

                     &gt;                         <a href="https://members.accu.org/index.php/articles/c408/">321</a>
<br />

                                            <a href="https://members.accu.org/index.php/articles/c183-408/">Any of these categories</a>

                    -                        <a href="https://members.accu.org/index.php/articles/c183+408/">All of these categories</a>
<br />
</td>
   </tr>
   </tbody>
</table>




<div class="xar-error">
   <p>
 <strong>Note:</strong> when you create a new publication type,
the articles module will automatically use the templates
<em>user-display-[publicationtype].xt</em>
and <em>user-summary-[publicationtype].xt</em>.
If those templates do not exist when you try to preview or display a new article,
you'll get this warning :-)  Please place your own templates in themes/<em>yourtheme</em>/modules/articles . The templates will get the extension .xt there. </p>
</div>
<div class="xar-norm xar-standard-box-padding">
   <h1><strong>Title:</strong>&nbsp;Code Critique Competition 122</h1>
<p><strong>Author:</strong>&nbsp;Bob Schmidt</p>
<p>
<strong>Date:</strong> 03 March 2020 22:52:23 +00:00 or Tue, 03 March 2020 22:52:23 +00:00</p>
<p><strong>Summary:</strong>&nbsp;Set and collated by Roger Orr. A book prize is awarded for the best entry.</p>
<p><strong>Body:</strong>&nbsp;<p class="EditorIntro">Please note that participation in this competition is open to all members, whether novice or expert. Readers are also encouraged to comment on published entries, and to supply their own possible code samples for the competition (in any common programming language) to scc@accu.org.</p>

<p class="EditorIntro">Note: if you would rather not have your critique visible online please inform me. (Email addresses are not publicly visible.)</p>

<h2>Last issueâ€™s code</h2>

<p class="blockquote">I wanted to offload logging to the console from my main processing threads, so I thought Iâ€™d try to write a simple asynchronous logger class to help me do that (and hopefully learn something about threading while Iâ€™m doing it). Unfortunately it only prints the first line (or sometimes the first couple) and Iâ€™m not really sure how best to debug this as the program doesnâ€™t seem to behave quite the same way in the debugger.</p>

<pre class="programlisting">
     $ queue.exe
     main thread
     Argument 0 = queue.exe</pre>
	 
<p class="blockquote">or sometimes only:</p>

<pre class="programlisting">
     $ queue.exe
     main thread</pre>

<p>The coding is in three listings:</p>

<ul>
	<li>Listing 1 contains <span class="filename">async_logger.h</span></li>
	<li>Listing 2 contains <span class="filename">async_logger.cpp</span> </li>
	<li>Listing 3 contains <span class="filename">queue.cpp</span>.</li>
</ul>

<table class="sidebartable">
	<tr>
		<td>
			<pre class="programlisting">
#pragma once

#include &lt;iostream&gt;
#include &lt;queue&gt;
#include &lt;string&gt;
#include &lt;thread&gt;

using std::thread;

class async_logger
{
  bool active_;
  std::queue&lt;std::string&gt; queue_;
  thread thread_ { [this]() { run(); } };
  
  void run();
  
public:
  async_logger();
  ~async_logger();
  void log(const std::string &amp;str);
};
			</pre>
		</td>
	</tr>
	<tr>
		<td class="title">Listing 1</td>
	</tr>
</table>

<table class="sidebartable">
	<tr>
		<td>
			<pre class="programlisting">
#include &quot;async_logger.h&quot;
#include &lt;iostream&gt;
using std::thread;

// This runs in a dedicated thread
void async_logger::run()
{
  while (active_)
  {
    if (!queue_.empty())
    {
      std::cout &lt;&lt; queue_.front() &lt;&lt; '\n';
      queue_.pop();
    }
  }
}
async_logger::async_logger()
{
  active_ = true;
  thread_.detach();
}
async_logger::~async_logger()
{
  active_ = false;
}

// queue for processing on the other thread
void async_logger::log(const std::string &amp;str)
{
  queue_.emplace(str);
}
			</pre>
		</td>
	</tr>
	<tr>
		<td class="title">Listing 2</td>
	</tr>
</table>

<table class="sidebartable">
	<tr>
		<td>
			<pre class="programlisting">
#include &quot;async_logger.h&quot;

int main(int argc, char **argv)
{
  async_logger logger;
  logger.log(&quot;main thread&quot;);
  thread test1([&amp;logger]() {
    logger.log(&quot;testing thread 1&quot;);
  });
  for (int idx = 0; idx &lt; argc; ++idx)
  {
    logger.log(&quot;Argument &quot;
      + std::to_string(idx) + &quot; = &quot;
      + argv[idx]);
  }
  logger.log(&quot;main ending&quot;);
  test1.join();
}
			</pre>
		</td>
	</tr>
	<tr>
		<td class="title">Listing 3</td>
	</tr>
</table>

<p class="EditorIntro">Note: I inadvertently elided an underscore in transcribing the code for publication. Iâ€™m sorry for any confusion.</p>

<h2>Critiques</h2>

<h3>Paul Floyd</h3>
<p>Letâ€™s start by running through â€˜mainâ€™ to see what should be happening.</p>

<ol>
	<li>An instance of <code>async_logger</code> is created on the stack. The constructor creates a thread with a lambda that executes the <code>run()</code> member, sets the active flag and detaches the thread that was just created.</li>
	
	<li>A log message is sent from <code>main()</code>.</li>
	
	<li>A thread is created with a lambda that captures the logger instance by reference, and sends a message.</li>
	
	<li>A <code>for</code> loop sends messages to the logger, one per command line argument.</li>
	
	<li>A final ending message is sent to the logger.</li>
	
	<li>The lambda thread from step 3 is joined.</li>
	
	<li><code>Logger</code> goes out of scope at the end of <code>main</code>. Its destructor clears the <code>active_</code> flag, causing <code>async_logger::run()</code> to terminate.</li>
</ol>

<p>On a semi-positive note, I see that the two threads that get created are either detached or joined. Creating detached threads is not recommended, see <a href="http://isocpp.github.io/CppCoreGuidelines/CppCoreGuidelines#Rconc-detached_thread">http://isocpp.github.io/CppCoreGuidelines/CppCoreGuidelines#Rconc-detached_thread</a>.</p>

<p>Now for the problems. Firstly, a nitpick. I donâ€™t like the member variable of <code>async_logger</code> called <code>thread</code>. The other members use a trailing underscore, so Iâ€™d prefer that to be <code>thread thread_</code>.</p>

<p>Next, there is a problem with the initialisation of <code>async_logger::active_</code>. The <code>async_logger</code> constructor will initialise its members in order of declaration. <code>active_</code> is first, but is not initialised. Next <code>queue_</code> is initialised, via its constructor. Next <code>thread</code> is initialised, as per the default member initialiser. In the body of the constructor, <code>active_</code> is set to <code>true</code> and <code>thread</code> is detached.</p>

<p>There is a data race on the <code>active_</code> member. If the uninitialised value is <code>false</code> and <code>thread</code> runs to the <code>while (active_)</code> test before the constructor body sets <code>active_</code> to <code>true</code> then <code>run()</code> will terminate.</p>

<p>To fix this, move the initialisation of <code>active_</code> either to the initializer list or use default member initialisation. For consistency, the latter is what I would recommend.</p>

<p>The next problem is also a data race. Read and write to <code>async_logger::queue_</code> are not controlled, and <code>std::queue</code> is not thread safe.</p>

<p>To fix this, we can add a <code>std::mutex</code> to <code>async_logger</code> and then use a <code>std::lock_guard</code> (with an extra scope) in <code>async_logger::run()</code> and <code>async_logger::log()</code>.</p>

<p>Are we done? No, there are still two more data races. They both involve the <code>async_logger</code> destructor. Firstly, there is a data race in the <code>active_</code> member. The destructor sets <code>active_</code> to <code>false</code>, but <code>run</code> could be reading it at the same time. To solve this we can make <code>active_</code> an atomic (e.g., <code>std::atomic&lt;bool&gt; active_;</code>). In general this sort of error is â€˜mostly harmlessâ€™ â€“ if the race condition triggers it will probably just mean that <code>run</code> does one more iteration. However, I would still advise fixing the issue. The last data race concerns the destruction of <code>queue_</code>. The <code>run</code> thread could be accessing this member while the main thread destructor is destroying it. Unfortunately, thereâ€™s no easy way in the destructor to know when the <code>run</code> thread has terminated (and so it is safe to destroy <code>queue_</code>). So here I suggest not detaching the <code>run</code> thread. Remove the <code>detach</code> from the constructor and add a <code>join</code> to the constructor. After the <code>join</code>, we know that the <code>run</code> thread has terminated, so it is safe to proceed with the default destruction of <code>queue_</code>.</p>

<p>Are we there yet? No, still a long way to go. The data races are fixed, but there are still two problems. The first is that <code>main()</code> does nothing to make sure that <code>async_logger::run()</code> has emptied <code>queue_</code> before it terminates (remember, the termination condition for run is that <code>active_</code> is <code>false</code>, not that <code>queue_</code> is empty. We can fix this by adding a loop to empty <code>queue_</code> in the <code>async_logger</code> destructor. </p>

<p>The last remaining issue is performance. <code>run()</code> is busy-polling. It will be using ~100% of a CPU as long as the application runs. The fix for this is to use thread communication, for instance a <code>std::condition_variable</code>. Add one as a member of <code>async_logger</code>, add a call to <code>notify_one</code> in <code>log</code> and add a <code>wait</code> in <code>run</code> (and change the <code>lock_guard</code> to <code>unique_guard</code>).</p>

<p>OK, now we are done. No more thread hazards or CPU hogging and no missing output.</p>

<p>I spotted most of the issues other than the destructor and falling off main just by looking at the code. For further testing I used Thread Sanitizer, Valgrind DRD and Valgrind Helgrind.</p>

<p>A bit now about tools. As an example, I ran the unmodified code with <code>clang++ -fsanitize=thread</code> and I got</p>

<pre class="programlisting">
  WARNING: ThreadSanitizer: data race (pid=89319)
  Read of size 1 at 0x7ffee1517890 by thread T1:
  #0 async_logger::run() async_logger.cpp:8
  (cc121:x86_64+0x1000015a0)
  
  [snip]
  
  Previous write of size 1 at 0x7ffee1517890 by
  main thread:
  #0 async_logger::async_logger()
  async_logger.cpp:19 (cc121:x86_64+0x1000018b8)</pre>
  
<p>Always test your thread code with a dynamic analysis tool!</p>

<p>Iâ€™ll finish with a few comments about the design. As always, you should consider reusing code or packages where possible. Iâ€™m sure that there are many existing packages for performing asynchronous logging. The code here only logs to standard output. A more complete system would have options to log to a file, syslog, Windows Events as a few examples. I would also expect some sort if severity level like critical, serious, warning and information, perhaps with an option to filter out levels. I have just one last point. Systems like this have a hard time with logging events that occur during program shutdown. How can I log an event from the destructor of an object that is a file static? <code>logger</code>, being local to <code>main()</code>, will have already been destroyed when static destructors start getting called.</p>

<h3>Ovidiu Parvu</h3>

<p>Let us assume throughout that two requirements need to be met by an <code>async_logger</code> object. Firstly an <code>async_logger</code> object can be used to log messages, which will be printed to the standard output in the order in which they were logged. Secondly the logged messages will be printed to the standard output on a separate thread. All messages should be printed to the standard output before the <code>async_logger</code> object is destructed.</p>

<p>There are four main issues with the implementation given in the listings provided.</p>

<p>First of all the code cannot be compiled successfully due to an undeclared identifier error. Specifically the <code>std::thread async_logger</code> data member is referred to as <code>thread_</code> at async_logger.cpp:20:3 but it is defined as <code>thread</code> in <span class="filename">async_logger.h</span>. Renaming the data member from <code>thread</code> to <code>thread_</code> as shown below, which would be consistent with the naming of other <code>async_logger</code> data members (e.g. <code>active_</code>), addresses this issue.</p>

<pre class="programlisting">
  // async_logger.h
  class async_logger
  {
    ...
    thread thread_ { [this]() { run(); } };
    ...
  };</pre>
  
<p>Secondly, the <code>active_</code> <code>async_logger</code> data member should be initialized with the value <code>true</code> when an <code>async_logger</code> object is constructed and before the <code>thread_</code> data member is initialized. Otherwise it may be possible for the <code>while (active_) { ... }</code> loop in the <code>run()</code> method to be executed before the value of <code>active_</code> is set to <code>true</code>, and therefore the <code>run()</code> method will finish executing before the <code>async_logger</code> object is constructed. In this case no logged messages would be printed to the standard output. To avoid this issue the <code>active_</code> data member is initialized with the value <code>true</code> using a default member initializer as shown below.</p>

<pre class="programlisting">
  // async_logger.h
  class async_logger
  {
    ...
    bool active_ = true;
    ...
  };
  // async_logger.cpp
  async_logger::async_logger()
  {
    thread_.detach();
  }</pre>
  
<p>Thirdly, read and write access from multiple threads to the <code>active_</code> and <code>queue_ async_logger</code> data members should be synchronized. Otherwise data races could occur. Access to the <code>active_</code> data member can be synchronized by changing the type of <code>active_</code> from <code>bool</code> to <code>std::atomic_bool</code> and importing the <code>&lt;atomic&gt;</code> header as follows.</p>

<pre class="programlisting">
  // async_logger.h
  #include &lt;atomic&gt;
  ...
  class async_logger
  {
    ...
    std::atomic_bool active_{true};
    ...
  };</pre>
  
<p>Conversely, access to the <code>queue_</code> data member can be synchronized using a <code>std::mutex</code>. The mutex needs to be used in different <code>async_logger</code> member functions and therefore will be added as a data member to the <code>async_logger</code> class. The mutex will be (unique) locked in the <code>run()</code> and <code>log(const std::string&amp;)</code> methods before accessing the <code>queue_</code> data member as follows. In addition the <code>&lt;mutex&gt;</code> header must be included in <span class="filename">async_logger.h</span>.</p>

<pre class="programlisting">
  // async_logger.h
  ...
  #include &lt;mutex&gt;
  ...
  class async_logger
  {
    ...
    std::mutex mutex_;
    ...
  };
  // async_logger.cpp
  // This runs in a dedicated thread
  void async_logger::run()
  {
    while (active_)
    {
      std::unique_lock&lt;std::mutex&gt; lock(mutex_);
      if (!queue_.empty())
      {
        std::cout &lt;&lt; queue_.front() &lt;&lt; '\n';
        queue_.pop();
      }
    }
  }
  // queue for processing on the other thread
  void async_logger::log(const std::string&amp; str)
  {
    std::unique_lock&lt;std::mutex&gt; lock(mutex_);
    queue_.emplace(str);
  }</pre>
  
<p>Fourthly, the thread used to print messages to the standard output should not be <code>detach()</code>â€™ed in the <code>async_logger</code> constructor, and should be <code>join()</code>â€™ed in the <code>async_logger</code> destructor, because otherwise it will not be possible to wait for all messages to be printed on this thread before the <code>async_logger</code> object is destructed. After removing the <code>thread_.detach()</code> statement from the <code>async_logger</code> constructor, the constructor definition body is empty. Therefore both the <code>async_logger</code> constructor declaration and definition can be removed. The updated <code>async_logger</code> destructor definition is given below.</p>

<pre class="programlisting">
  // async_logger.cpp
  async_logger::~async_logger()
  {
    active_ = false;
    thread_.join();
  }</pre>
  
<p>To ensure that all log messages are printed to the standard output before the <code>async_logger</code> is destructed, an additional loop is added to the <code>run()</code> method which prints all log messages remaining in <code>queue_</code> after <code>active_</code> is set to <code>false</code> and the <code>while (active_) { ... }</code> loop finishes executing. Both the newly added loop and the <code>while (active_) { ... }</code> loop pop the log messages from <code>queue_</code> and print the messages to the standard output. Therefore the log messages printing code can be extracted into a separate member function called <code>print_oldest_msg()</code> as follows.</p>

<pre class="programlisting">
  // async_logger.h
  class async_logger
  {
    ...
    void print_oldest_msg();
    ...
  };
  // async_logger.cpp
  // This runs in a dedicated thread
  void async_logger::run()
  {
    while (active_)
    {
      std::unique_lock&lt;std::mutex&gt; lock(mutex_);
      if (!queue_.empty()) print_oldest_msg();
    }
    while (!queue_.empty()) print_oldest_msg();
  }
  void async_logger::print_oldest_msg() {
    std::cout &lt;&lt; queue_.front() &lt;&lt; '\n';
    queue_.pop();
  }</pre>
  
<p>Additional minor improvements that could be made to the code given in provided listings are that the <code>using std::thread;</code> statements could be removed to avoid future potential name collisions should the project include user-defined thread type definitions in the future, and the unused <code>&lt;iostream&gt;</code> header include could be removed from <span class="filename">async_logger.h</span>.</p>

<p class="EditorIntro">[Ed: The code in Listings 2â€“4 updated according to all the changes described above was provided, but is omitted for brevity.] </p>


<h3>James Holland</h3>
<p>Some minor points. <code>#pragma once</code> is not standard C++. My version of <span class="filename">async_logger.h</span> uses the more universal method of writing Include Guards. The original code is missing a trailing underscore in the declaration of <code>thread_</code> within the <code>async_logger</code> class.</p>

<p>When I ran the software on my Linux system, it produced the desired output. This was unfortunate because it gave no hint as to what could be wrong. When the student ran the program, some of the expected output was missing. This suggests there are some problems with the ordering of events within the executing program. Some systems may order events in a different order than others. It is very difficult just by looking at the source code to determine the relative timing of events when multiple threads are involved. In an attempt to make some headway with this problem I constructed a timing diagram that is loosely based on the Unified Modelling Language (UML) sequence diagram as shown in Figure 1.</p>

<table class="sidebartable">
	<tr>
		<td><img src="/content/images/journals/cvu32-1/CCC/CCC-01.png" /></td>
	</tr>
	<tr>
		<td class="title">Figure 1</td>
	</tr>
</table>

<p>At the top of the diagram are the objects involved in the exchange of messages. The time axis runs from top to bottom. One feature that is revealed is that the execution of <code>async_logger</code>â€™s <code>run</code> functionâ€™s <code>while</code>-loop is dependent on value of the <code>active_</code> variable. Unfortunately, it is quite possible that the variable has not been assigned a value before it is read by the <code>while</code>-loop. The problem is that <code>active_</code> is not initialised as soon as it could be. It is assigned a value within the body of <code>async_logger()</code>. This gives time for the while-loop to read the uninitialised variable. Probably the simplest way of correcting this problem is to initialise <code>active_</code> to <code>true</code> within the class definition of <code>async_logger</code> (located in <span class="filename">async_logger.h</span>). Objects are initialised in the order they are declared within the class. Declaring (and initialising) <code>active_</code> before <code>thread_</code> ensures <code>active_</code> is set to the required value before it is read by <code>thread_</code>. The assignment of <code>active_</code> within the body of <code>async_logger</code>â€™s constructor can now be removed.</p>

<p>The sequence diagram also reveals a problem when logger is terminated. There is no guarantee that the calls to <code>empty()</code> and <code>pop()</code> will access a valid version of <code>queue_</code> or that <code>active_</code> exists when an attempted is made to access it by <code>run()</code>. Perhaps the simplest way to ensure these objects are still valid when accessed is for the destructor of <code>async_logger</code> to call <code>thread_</code>â€™s <code>join()</code> function instead of the constructor of <code>async_logger</code> calling <code>thread_</code>â€™s <code>detach()</code> function.</p>

<p>The compiler and the processor hardware are capable of optimising the program in ways that include altering the order in which instructions are executed as long as the result of a single thread of execution is the same as for the unaltered program. This can cause problems when two or more threads interact. In the program in question it is important that <code>active_</code> is assigned a value at the appropriate time relative other instructions. To prevent such reordering, the type of <code>active_</code> should be changed from <code>bool</code> to <code>atomic_bool</code>.</p>

<p>With any luck, the program is now producing the desired result. The program relies on luck because the C++ standard makes no guarantees about the correct operation of <code>std::queue</code> when working in a multi-threaded environment. What is needed is a thread-safe queue. Such queues are a little involved and I do not intend to explore their construction here. One of the best sources of information regarding threads and concurrency in general is the book by Anthony Williams, <em>C++ Concurrency in Action</em>, second edition, ISBN 978-1617294-69-3. Here, various thread-safe queues are discussed and are worthy of study. Implementing a thread-safe queue will remove the element of luck.</p>

<p>There is another interesting aspect to the studentâ€™s code. The function <code>run()</code> belonging to <code>async_logger</code> contains a loop that continually tests for items in the queue. This is wasteful of processor resources. It would be better for the <code>async_logger</code> thread to â€˜sleepâ€™ when there is nothing in the queue and to be â€˜wokenâ€™ when something is added to the queue. Such a facility is provided by condition variables.</p>

<p>I have added a mutex, <code>m</code>, and a condition variable, <code>data_available</code>, to global scope. I have modified <code>async_logger</code>â€™s <code>log</code> function by changing the <code>if</code> statement for another <code>while</code>-loop and created a <code>unique_lock</code> object using the mutex <code>m</code>. A call is then made to <code>data_available</code>â€™s <code>wait()</code> function. <code>In log()</code>, I have added a call to <code>data_available</code>â€™s <code>notify_one()</code> function just after an item has been placed on the queue. In this way a thread can block on the <code>wait()</code> function until awoken by <code>notify_one()</code>.</p>

<p>Arranging for <code>run()</code> to break out of the <code>while</code>-loop is a little tricky. I have chosen to wake-up the blocked thread with another call to <code>notify_one()</code> just after setting <code>active_</code> to <code>false</code>. This requires a modification to <code>waits()</code>â€™s lambda so that execution can continue if <code>active_</code> is false. An <code>if</code> statement is also added after the newly added <code>while</code>-loop of <code>run()</code> that has the effect of returning from <code>run()</code> when <code>active_</code> is <code>false</code>. Another way to return from <code>run()</code> is to recognise a special message placed on the queue and to return when it is detected.</p>

<p>I provide my version of the code despite it not having a thread-safe queue. It may be instructive, however. </p>

<pre class="programlisting">
  --- async_logger.cpp ---
  #include &quot;async_logger.h&quot;
  #include &lt;iostream&gt;
  std::mutex m;
  std::condition_variable data_available;
  using std::thread;
  // This runs in a dedicated thread
  void async_logger::run()
  {
   while (true)
    {
      std::unique_lock&lt;std::mutex&gt; lock(m);
      data_available.wait(lock, [this]{
        return !queue_.empty() || !active_;});
      while (!queue_.empty())
      {
        std::cout &lt;&lt; queue_.front() &lt;&lt; '\n';
        queue_.pop();
      }
      if (!active_)
      {
        return;
      }
    }
  }
  async_logger::~async_logger()
  {
    active_ = false;
    data_available.notify_one();
    thread_.join();
  }
  // queue for processing on the other thread
  void async_logger::log(const std::string &amp;str)
  {
    queue_.emplace(str);
    data_available.notify_one();
  }

  --- async_logger.h ---
  #ifndef ASYNC_LOGGER
  #define ASYNC_LOGGER
  #include &lt;iostream&gt;
  #include &lt;queue&gt;
  #include &lt;string&gt;
  #include &lt;thread&gt;
  #include &lt;atomic&gt;
  #include &lt;mutex&gt;
  #include &lt;condition_variable&gt;
  using std::thread;
  class async_logger
  {
  private:
    std::atomic_bool active_ = true;
    std::queue&lt;std::string&gt; queue_;
    thread thread_{[this](){run();}};
    void run();
  public:
    ~async_logger();
    void log(const std::string &amp;str);
  };
  #endif
  
  --- queue.cpp ---
  #include &quot;async_logger.h&quot;
  int main(int argc, char **argv)
  {
    async_logger logger;
    logger.log(&quot;main thread&quot;);
    thread test1([&amp;logger](){
      logger.log(&quot;testing thread 1&quot;);});
    for (int idx = 0; idx &lt; argc; ++idx)
    {
      logger.log(&quot;Argument &quot; +
        std::to_string(idx) + &quot; = &quot; +
        argv[idx]);
    }
    logger.log(&quot;main ending&quot;);
    test1.join();
  }</pre>

<h3>Hans Vredeveld</h3>

<p>In making the authorâ€™s code available to us for review, the variable <code>thread_</code> lost its underscore in the declaration on line 14 of <span class="filename">async_logger.h</span>. After correcting this, the code compiled and ran with the behaviour as described by the author.</p>

<p>One thing that testing this program makes clear, is that testing multi-threaded programs is hard. When I run the program with four arguments, I had to run it 27 times before I got something different than the expected output. When I run it with the complete alphabet as program arguments, it usually didnâ€™t give the expected output, but stopped somewhere after outputting the letter m.</p>

<p>Before we delve into the real issues with the code, letâ€™s get some annoyances out of the way.</p>

<p>Following the mantra â€˜include what you use and nothing elseâ€™, <code>#include &lt;iostream&gt;</code> should be removed from <span class="filename">async_logger.h</span>, and <span class="filename">queue.cpp</span> should have <code>#include</code>s for <code>&lt;string&gt;</code> and <code>&lt;thread&gt;</code>.</p>

<p>Unscoped <code>using</code> declarations in headers should be avoided at all times and used with extreme care in implementation files. They can cause conflicts with identifiers that a user defines herself. At best this will result in a compiler error. At worst it will compile and link without any error or warning, but use the wrong declaration. We can remove the <code>using</code> declaration for <code>std::thread</code> in <span class="filename">async_logger.h</span> and qualify the types of <code>thread_</code> in <span class="filename">async_logger.h</span> and <code>test1</code> in <span class="filename">queue.cpp</span> with <code>std::</code>. The <code>#using std::thread</code> in <span class="filename">async_logger.cpp</span> serves no purpose at all and should be removed.</p>

<p>The last annoyance is the parameter of <code>async_logger::log</code>. Its type is <code>std::string const&amp;</code>, and this forces the compiler to always copy the string into the queue. Especially for a log-function, that is called with a temporary object most of the time, it would be nice if we could use move semantics. Changing the function to</p>

<pre class="programlisting">
  void async_logger::log(std::string str)
  {
    queue_.emplace(std::move(str));
  }</pre>
  
<p>makes this possible. Of course, <span class="filename">async_logger.cpp</span> now must <code>#include &lt;utility&gt;</code>.</p>

<p>Now that the annoyances are out of the way, letâ€™s focus on the real problems. The first thing to notice is that in <code>async_logger</code>, <code>thread_</code> has a default member initializer and that <code>active_</code> is not initialized until inside the constructor body. Depending on thread scheduling, this could mean that <code>thread_</code> starts executing <code>async_logger::run</code> while <code>active_</code> is still not initialized and might have the value <code>false</code>. The <code>while</code>-loop in <code>async_logger::run</code> might thus never be executed. The solution to this problem is to remove the initialization of <code>active_</code> from the constructor's body and move it to the member initializer list or to a default member initializer. Also, <code>active_</code> is used from multiple threads and not only for reads. Therefore, it should be an <code>std::atomic_bool</code> instead of a <code>bool</code>.</p>

<p>More on <code>thread_</code>. In <code>async_logger</code>â€™s constructor the thread that it creates is detached. Consequently, the lifetime of the running thread is not connected to the lifetime of the <code>async_logger</code> instance that created it any more. The thread keeps on running when the <code>async_logger</code> instance that it is using, is destroyed, resulting in undefined behaviour. To solve this, remove <code>thread_.detach()</code> from the constructor and add <code>thread_.join()</code> to the destructor after setting <code>active_</code> to <code>false</code>. Note that, if <code>active_</code> was initialized by a member initializer, now there is no need to define the constructor explicitly any more, and we can leave it to the compiler to generate one.</p>

<p>Now, when <code>active_</code> becomes <code>false</code>, the thread will drop out of the <code>while</code>-loop in <code>async_logger::run</code> and the thread will exit. Also, each time the body of the while-loop is executed and there are messages in the queue, only one message is printed. So when the thread drops out of the while-loop, any remaining messages in the queue are not printed, which is the behaviour that the student observed. By changing the if-statement to a while-statement, we make sure that all messages in the queue are printed before <code>active_</code> is checked again.</p>

<p>While it now looks like we have the behaviour that the student wanted, there are still two issues with the code. First, <code>std::queue</code> is not thread safe. Second, <code>async_logger::run</code> uses a busy wait for <code>queue_</code> to be filled again. We can solve these issues with a mutex and a condition variable. First, we add them as private members to the <code>async_logger</code> class in <span class="filename">async_logger.h</span>:</p>

<pre class="programlisting">
  std::mutex mutex_;
  std::condition_variable cv_;</pre>
  
<p>Of course, we must also <code>#include &lt;mutex&gt;</code> and <code>&lt;condition_variable&gt;</code>. Now before we add a message to the queue in <code>async_logger::log</code>, we lock the mutex, and after we add the message, we notify a thread through the condition variable:</p>

<pre class="programlisting">
  void async_logger::log(std::string str)
  {
    std::lock_guard&lt;std::mutex&gt; lock(mutex_);
    queue_.emplace(std::move(str));
    cv_.notify_one();
  }</pre>
  
<p>Now <code>async_logger::run</code> is a bit more complex:</p>

<pre class="programlisting">
  void async_logger::run()
  {
    while (true)
    {
      std::queue&lt;std::string&gt; q;
      {
        std::unique_lock&lt;std::mutex&gt;
          lck(mutex_);
        cv_.wait(lck,
          [this](){ return !(queue_.empty() &amp;&amp;
                             active_); });
        if (queue_.empty() &amp;&amp; !active_)
            return;
        q = std::move(queue_);
        queue_ = std::queue&lt;std::string&gt;();
      }
      while (!q.empty())
      {
        std::cout &lt;&lt; q.front() &lt;&lt; '\n';
        q.pop();
      }
    }
  }</pre>
  
<p>We need to hold a lock on <code>mutex_</code> when we are accessing <code>queue_</code>, but we donâ€™t want to hold the lock when printing the messages. Therefore, we move the messages to a local queue <code>q</code>, reinitialize <code>queue_</code> as an empty queue and release the lock before we print the messages from the local queue.</p>

<p>Also, we let the thread sleep until there is something in <code>queue_</code> or the async logger has become inactive. To make sure that we print the last messages, we change the outer <code>while</code>-loop into a perpetual loop and in its body explicitly return from the function when <code>queue_</code> is empty and <code>active_</code> is false. </p>

<h2>Commentary</h2>

<p>This simple looking example has multiple problems and goes to show, in Hansâ€™s words â€œthat testing multi-threaded programs is hardâ€.</p>

<p>The wording for this critique says the user is trying to write some logging to offload work from their main thread, and thought theyâ€™d use this as a chance to â€œlearn something about threadingâ€. I would avoid trying to learn threading <em>indirectly</em> like this as there are too many â€˜sharp edgesâ€™ and the resultant code may well be buggy. Better to work through a tutorial or a book, such as Anthonyâ€™s <em>C++ Concurrency in Action</em> that James mentioned. </p>

<p>As far as the code itself goes, the entrants between them did a great job of finding the problems, explaining what was wrong, and providing solutions, so I donâ€™t have a huge amount to add.</p>

<p>One concern I had over Jamesâ€™ solution is that he uses <em>global</em> variables <code>m</code> and <code>data_available</code>, which could cause link-time problems (and also have a potential static initialisation order problem).</p>

<p>All the critiques fixed the race condition in <code>active_</code>, then made it an <code>atomic_bool</code> for thread-safety reasons, and then added a mutex to make access to the queue thread-safe. Once the mutex was added I think the change to <code>atomic_bool</code> should be reverted (and the variable accessed while the mutex is locked) as there are <em>two</em> conditions for the thread to check and using a single synchronisation mechanism makes it easier to avoid threading errors, such as deadlock.</p>

<p>The original code had a potential inefficiency over copying temporary strings; Hans changed the function to take a string by value which is an optimisation for temporary strings and at least no worse for others. Should measurement indicate the performance of this method is a problem, there are other possibilities to investigate such as adding overloads for common use cases.</p>

<p>A note on <code>#pragma once</code>. While this is non-standard, it is very widely supported. There was at least one proposal to standardise this (wg21.link/p0538), but it was rejected in Kona 2017.</p>

<h2>The winner of CC 121</h2>

<p>All four critiques covered the major problems with the code and produced a solution that fixes the errors. Some additionally pointed out that the reading thread is using a busy loop and corrected this using a condition variable â€“ this is probably the correct thing to do, unless latency is critical!</p>

<p>Diagrams like the one that James made use of can be really useful in a threading algorithm in identifying the dependencies and possible errors in logic, such as race conditions. This can be done in conjunction with dynamic analysis tools, such as those that Paul describes.</p>

<p>I liked Ovidiuâ€™s introduction of a helper function <code>print_oldest_msg</code> as this made a separation between the logic of handling the queue and the work of processing the contents. While it doesnâ€™t make too much difference in such short examples, this is the sort of separation of concerns that can make code significantly easier to understand.</p>

<p>Paul ends his critique by raising some of the design issues with logging and recommends looking for an existing package. I consider that may be the best advice in this case. Ovidiuâ€™s opening paragraph lists two basic requirements of an asynchronous logger, which could be the basis of a check list for looking for a third-party logger.</p>

<p>There is a problem with â€˜livenessâ€™ in that the first three solutions process the message in the logging thread with the mutex locked. This blocks the main thread if it tries to log again during the I/O. Hansâ€™s solution ensures that the processing of the queue of messages happens outside of the lock. (I think rather than moving from the queue and assigning a default constructed one it might be simpler to just swap the two queues over.)</p>

<p>Ending gracefully remains a potential problem: both Paulâ€™s and Hansâ€™s critiques as they stand contains a possible deadlock on exit as the <em>destructor</em> also needs modifying when the condition variable and mutex are added to ensure it notifies the condition variable. Without this change the code could hang on exit if the logging thread is inside the call to <code>wait</code>. when the value of <code>active_</code> is changed.</p>

<p>Overall there were four good critiques here, but I thought that Paulâ€™s discussion of dynamic analysis tools and his closing comments on the design made his critique broader in coverage and I have awarded him the prize for this issueâ€™s critique.</p>

<h2>Code Critique 121</h2>

<p>(Submissions to scc@accu.org by April 1st)</p>

<p class="blockquote">I was set a challenge to read the â€˜Top 100 booksâ€™ (from the BBC Big Read a few years ago) so thought I could start by seeing which ones I needed to get. Obviously this meant writing a program. Unfortunately, the output from the program isnâ€™t sorted, although I was expecting it would be; and in addition, it crashed on Windows.</p>

<p>Can you help the author fix their program so they can begin to catch up with their reading? The program (<span class="filename">the_big_read.cpp</span>) is in Listing 4.</p>

<table class="sidebartable">
	<tr>
		<td>
			<pre class="programlisting">
#include &lt;algorithm&gt;
#include &lt;iostream&gt;
template &lt;int A, int B&gt;
void to_buy(const char *(&amp;to_read)[A],
  const char *(&amp;own)[B])
{
  const char** ptr = new const char *[A];
  const char **first = ptr;
  for (int i = 0; i != A; ++i)
  {
    *ptr++ = to_read[i];
    for (int j = 0; j != B; ++j)
    {
      if (!strcmp(to_read[i], own[j]))
      {
        ptr--; // already own it!
      }
    }
  }
  std::sort(first, ptr);
  for (const char **q = first; q != ptr; ++q)
    std::cout &lt;&lt; *q &lt;&lt; std::endl;
  delete ptr;
}
int main()
{
  const char* top_100 [] = {
    &quot;The Lord of the Rings&quot;,
    &quot;Pride and Prejudice&quot;,
    &quot;His Dark Materials&quot;,
    &quot;The Hitchhiker's Guide to the Galaxy&quot;,
    // 93 missing ...
    &quot;Girls In Love&quot;,
    &quot;The Princess Diaries&quot;,
    &quot;Midnight's Children&quot;,
    };
  const char* my_library[] = {
    &quot;The Hitchhiker's Guide to the Galaxy&quot;,
    &quot;Vintage Jeeves&quot;,
    // and many more ...
    &quot;His Dark Materials&quot;,
    &quot;Pride and Prejudice&quot;,
    &quot;Emma&quot;,
    &quot;Where Eagles Dare&quot;,
    };
  to_buy(top_100, my_library);
}
			</pre>
		</td>
	</tr>
	<tr>
		<td class="title">Listing 4</td>
	</tr>
</table>

<p>You can also get the current problem from the accu-general mail list (next entry is posted around the last issueâ€™s deadline) or from the ACCU website (<a href="http://accu.org/index.php/journal">http://accu.org/index.php/journal</a>&lt;/XRef&gt;
). This particularly helps overseas members who typically get the magazine much later than members in the UK and Europe.</p>

<p class="bio"><span class="author"><b>Roger Orr</b></span> has been programming for over 20 years, most recently in C++ and Java for various investment banks in Canary Wharf and the City. He joined ACCU in 1999 and the BSI C++ panel in 2002.</p>
</p>
<p><strong>Notes:</strong>&nbsp;</p>
<p><em>More fields may be available via dynamicdata ..</em></p>
</div>
</channel>
</rss>
