Logger logs 2 times instead of one time because of copy

Question

I am writing my own Logger. I know there are alot out there but i would like to write it myself. It has messages which get logged when they are leaving the scope. So if i call Logger::Error(__FILE__,__LINE__) << "some error" it gets logged directly since there is no assignemnt to a variable.

But i would like to have a message which logs the time of the scope. So it mesures the time since creation and since delete. Therefore i need it to be assigned to a variable in the scope with for example this marko: #define LOG_SCOPE_TIME LogTimer ___t = Logger::Timer(__FILE__,__LINE__) It can be used like this:

int main()
{
    {
    LOG_SCOPE_TIME << "Some scope";
    //do something to mesure
    }
}

Example output:

[timer][File:main.cpp][Line:19][thread:8024][21-05-2015][13:15:11] Some scope[0µs]
[timer][File:main.cpp][Line:19][thread:8788][21-05-2015][13:15:11] Some scope[118879µs]

But this actually causes 2 logs. The first of the temporary created LogTime object (with time 0µs) and the second with the real scope time.

How do i prevent from this? Any suggestions? Here is a reduced example:

#include <iostream>
#include <chrono>

class LogTimer {
    std::string str;
    std::chrono::high_resolution_clock::time_point m_start;
public:
    LogTimer(const std::string& file, int i)
        : m_start(std::chrono::high_resolution_clock::now())
    {
        str = file + ':' + std::to_string(i);
    }

    ~LogTimer() {
        auto end = std::chrono::high_resolution_clock::now();
        auto duration = std::chrono::duration_cast<std::chrono::microseconds>
                    (end - m_start).count();
        std::cout << str << " [" << duration << "µs]\n";
    }

    LogTimer& operator<<(const std::string& p) {
        str += '[' + p + ']';
        return *this;
    }
};

namespace Logger {
    LogTimer Timer(const std::string& f, int i) {
        return LogTimer(f, i);
    }
}

#define LOG_SCOPE_TIME LogTimer ___t = Logger::Timer(__FILE__,__LINE__)

int main() 
{
    LOG_SCOPE_TIME << "something"; // logs two lines
}

Answer 1

You're running into an operator precedence issue, sort of. When you use your macro:

LOG_SCOPE_TIME << "Some scope";

That expands into:

LogTimer ___t = Logger::Timer(__FILE__,__LINE__) << "Some scope";

Which gets evaluated as:

LogTimer ___t = (Logger::Timer(__FILE__,__LINE__) << "Some scope");

since << has higher precedence than =. As such, you are preventing copy elision from happening since the compiler has to now create a temporary Timer to perform the << "Some Scope" and then copy it into ___t (which is technically a reserved name). The additional copy means an addition destructor, which in your case means an extra line logged.

You need to ensure copy elision. The simplest way I can think of is to change your macro to do:

#define LOG_SCOPE_TIME LogTimer ___t = Logger::Timer(__FILE__,__LINE__); ___t

That way, your original example expands to:

LogTimer ___t = Logger::Timer(__FILE__,__LINE__); ___t << "Some scope";

No issues there.