C++日志记录和性能优化库

Question

我需要在Windows上对一些实时代码进行性能分析。

由于不能减慢可执行文件的速度，因此我无法使用任何常规的分析工具（如Vtune、Codeanalyst）。因此，我使用基于QueryPerformanceCounter()的自己编写的定时类。

是否存在任何现有的（免费）C++库来记录结果 - 但我需要它们缓冲到运行结束，我不能花时间在收集数据时写入文件或事件日志。

可以很容易地自行开发，但如果有一种方法可以使log4cplus / qDebug或类似的记录到缓冲区并稍后转储，那就可以节省一些工作量。

- Martin Beckett

---

请注意，记录日志的行为仍会通过破坏缓存和消耗内存带宽来减慢您的可执行文件。此外，如果我没记错，QueryPerformanceCounter()比直接调用RDTSC要慢得多。 - EmeryBerger

此外，Windows 上的 VTune 可以进行基于事件的采样，这不会对您的代码造成任何影响。 - EmeryBerger

或者您可以尝试使用xperf和ETW。在您的情况下，由于您拥有VTune，EmeryBerger已经在上面评论中提供了解决方案。 - Peon the Great

Vtune无法告诉您从获取网络事件到完成处理结果之间的时间。Xperf等工具可以告诉我机器在内核函数中花费了大量时间，但无法解释为什么FPS低。AMD无法基于Intel CPU进行事件跟踪，而VTUNE价格昂贵。 - Martin Beckett

@EmeryBerger - 是的，你不能用它来计时整数加法。但在毫秒级别上，了解某个调用是否阻塞，或者任务是否花费比我想象的更长时间是可以的。 - Martin Beckett

测量是一回事，但如果您想看看在哪里进行更改以加快速度，下面是我的做法。使其高效运行，然后手动关闭它。记录栈。多次操作。这不会减慢速度，只会停止它。如果您在两个或更多样本中看到任何代码，如果您可以进行优化，将为您提供健康的速度提升。 - Mike Dunlavey

Answer 1

我也写了一个类来实现这个功能，因为我找不到任何可以满足我的要求并且易于与现有代码集成的东西，只需复制粘贴编码技术即可。

（编辑）请注意，正如评论中提到的那样，计时本身会改变你正在计时的事物的性质。但我相信您已经非常了解这一点了。这个类对我仍然非常有用，可以找到热点和瓶颈，并且至少给出某些代码运行所需时间的粗略高估值。我在这里呈现的代码从未旨在达到生产级别。请勿将其用于此目的。

以下是我的类的示例输出：

Timer Precision = 385 ns


=== Item               Trials    Ttl Time  Avg Time  Mean Time StdDev    ===
    DB Connect         1         0.11 s    0.11 s    0.11 s    0.0000 ps
    Entry Parse        3813      0.33 s    86 us     82 us     18 us
    File Load          1         50 ms     50 ms     50 ms     0.0000 ps
    Option Parse       1         5 ms      5 ms      5 ms      0.0000 ps
    Record Update      3812      0.53 s    140 us    127 us    49 us
============================================================================

每个"Item"都是我想计时的代码部分。 Timer对象使用RAII（通过auto_ptr）允许自动启动和停止。以下是一些演示如何使用它的客户端代码示例：

示例代码：

int main(int ac, char* av[])
{
    std::auto_ptr<dbg::Timer> section_timer(new dbg::Timer("Option Parse"));
    // MAGIC: Parse the command line...

    section_timer = auto_ptr<dbg::Timer>(new dbg::Timer("File Load"));
    // MAGIC: Load a big file...        

    section_timer = auto_ptr<dbg::Timer>(new dbg::Timer("DB Connect"));
    // MAGIC: Establish a DB connection...

    for( /* for each item in the file*/  )
    {
      section_timer = auto_ptr<dbg::Timer>(new dbg::Timer("Entry Parse"));
      // MAGIC: Parse the incoming item
      section_timer = auto_ptr<dbg::Timer>(new dbg::Timer("Record Update"));
      // MAGIC: Update the database
    }

    // Dump the output shown above    

    cout << dbg::Timer::DumpTrials() << endl;
}

这个类的实现在一个包含库中。您不需要编译任何东西。我使用Boost.Format来进行字符串格式化，但这可以很容易地替换。

以下是实现代码（我的实际实现将其分成两个文件，core.h和core_dbg.hpp；后者直接从前者#include）。

实现：

namespace dbg
{
    class Timer
    {
    public:
        inline Timer(const std::string & name);
        inline Timer(const Timer& rhs);
        inline virtual ~Timer();
        inline std::string format_now() const;
        double current_elapsed() const;

        Timer& operator=(const std::string& name);

        static std::string DumpTrials(bool ClipboardAlso=false);            
        static void Reset();
        static std::string format_elapsed(double d) ;

    private:
        typedef std::string key_type;
        typedef double time_type;
        typedef std::multimap<key_type, time_type> times;

        static __int64 TimerFreq();

        LARGE_INTEGER startTime_, stopTime_;
        mutable LARGE_INTEGER intermediateTime_;
        std::string label_;

        static times& TimeMap();

        struct extract_key : public std::unary_function<times::value_type, key_type>
        {
            std::string operator()(times::value_type const & r) const
            {
                return r.first;
            }
        };

        struct extract_val : public std::unary_function<times::value_type, time_type>
        {
            time_type operator()(times::value_type const & r) const
            {
                return r.second;
            }
        };
        struct match_key : public std::unary_function<times::value_type, bool>
        {
            match_key(key_type const & key_) : key(key_) {};
            bool operator()(times::value_type const & rhs) const
            {
                return key == rhs.first;
            }
            match_key& operator=(const match_key& rhs)
            {
                key = rhs.key;
                return * this;
            }
        protected:
            key_type key;
        };

        struct accum_key : public std::binary_function<time_type, times::value_type, time_type>
        {
            accum_key(key_type const & key_) : key(key_), n(0) {};
            time_type operator()(time_type const & v, times::value_type const & rhs) const
            {
                if( key == rhs.first )
                {
                    ++n;
                    return rhs.second + v;
                }
                return v;
            }
        private:
            times::key_type key;
            mutable size_t n;
        };
    };

    inline Timer::Timer(const std::string & name)
    {
        label_ = name;
        QueryPerformanceCounter(&startTime_);
    }

    inline double Timer::current_elapsed() const
    {
        QueryPerformanceCounter(&intermediateTime_);
        __int64 clocks = intermediateTime_.QuadPart-startTime_.QuadPart;
        double elapsed = (double)clocks/(double)TimerFreq();
        return elapsed;
    }

    inline Timer::~Timer()
    {
        double elapsed = current_elapsed();
        stopTime_.QuadPart = intermediateTime_.QuadPart;
        TimeMap().insert(std::make_pair(label_,elapsed));
    };

    inline Timer& Timer::operator=(const std::string& name)
    {
        double elapsed = current_elapsed();
        stopTime_.QuadPart = intermediateTime_.QuadPart;
        TimeMap().insert(std::make_pair(label_,elapsed));
        label_ = name;
        QueryPerformanceCounter(&startTime_);
        return * this;
    }

    inline Timer::Timer(const Timer& rhs)
    {
        double elapsed = current_elapsed();
        stopTime_.QuadPart = intermediateTime_.QuadPart;
        TimeMap().insert(std::make_pair(label_,elapsed));
        label_ = rhs.label_;
        QueryPerformanceCounter(&startTime_);
    }

    inline std::string Timer::format_now() const
    {
        return format_elapsed(current_elapsed());
    }

    inline std::string Timer::DumpTrials(bool ClipboardAlso)
    {
        using boost::io::group;

        if( TimeMap().empty() )
        {
            return "No trials\r\n";
        }

        std::string ret = (boost::format("\r\n\r\nTimer Precision = %s\r\n\r\n")
            % format_elapsed(1.0/(double)TimerFreq())).str();

        // get a list of keys
        typedef std::set<std::string> keyset;
        keyset keys;
        std::transform(TimeMap().begin(), TimeMap().end(), std::inserter(keys, keys.begin()), extract_key());

        size_t maxrows = 0;

        typedef std::vector<std::string> strings;
        strings lines;

        static const size_t t = 9;

        std::string head = 
            (boost::format("=== %-s %-s %-s %-s %-s %-s ===") 
            //% (t*2) 
            //% (t*2) 
            % group(std::setw(t*2), std::setprecision(t*2), "Item" )
            //% t 
            //% t 
            % group(std::setw(t), std::setprecision(t), "Trials")
            //% t 
            //% t 
            % group(std::setw(t), std::setprecision(t),  "Ttl Time" )
            //% t 
            //% t 
            % group(std::setw(t), std::setprecision(t), "Avg Time" )
            //% t 
            //% t 
            % group(std::setw(t), std::setprecision(t),  "Mean Time" )
            //% t 
            //% t 
            % group(std::setw(t), std::setprecision(t),  "StdDev")
            ).str();

        ret += (boost::format("\r\n%s\r\n") % head).str();
        if( ClipboardAlso ) 
            lines.push_back("Item\tTrials\tTtl Time\tAvg Time\tMean Time\tStdDev\r\n");
        // dump the values for each key
        for( keyset::iterator key = keys.begin(); keys.end() != key; ++key )
        {
            time_type ttl = 0;
            ttl = std::accumulate(TimeMap().begin(), TimeMap().end(), ttl, accum_key(*key));
            size_t num = std::count_if( TimeMap().begin(), TimeMap().end(), match_key(*key));
            if( num > maxrows ) 
                maxrows = num;
            time_type avg = ttl / num;

            // compute mean
            std::vector<time_type> sortedTimes;
            dibcore::stl::transform_if(TimeMap().begin(), TimeMap().end(), std::inserter(sortedTimes, sortedTimes.begin()), extract_val(), match_key(*key));
            std::sort(sortedTimes.begin(), sortedTimes.end());
            size_t mid = (size_t)floor((double)num/2.0);
            double mean = ( num > 1 && (num % 2) != 0 ) ? (sortedTimes[mid]+sortedTimes[mid+1])/2.0 : sortedTimes[mid];

            // compute variance
            double sum = 0.0;
            if( num > 1 )
            {
                for( std::vector<time_type>::iterator cur = sortedTimes.begin(); sortedTimes.end() != cur; ++cur )
                    sum += pow(*cur-mean,2.0);
            }

            // compute std dev
            double stddev = num > 1 ? sqrt(sum/((double)num-1.0)) : 0.0;

            ret += (boost::format("    %-s %-s %-s %-s %-s %-s\r\n") 
                % group(std::setw(t*2), std::setprecision(t*2) , (*key))
                % group(std::setw(t), std::setprecision(t) , (boost::format("%d") %num).str() )
                % group(std::setw(t), std::setprecision(t) , format_elapsed(ttl).c_str() )
                % group(std::setw(t), std::setprecision(t) , format_elapsed(avg) )
                % group(std::setw(t), std::setprecision(t) , format_elapsed(mean) )
                % group(std::setw(t), std::setprecision(t) , format_elapsed(stddev)) ).str(); 

            if( ClipboardAlso )
                lines.push_back((
                boost::format("%s\t%s\t%s\t%s\t%s\t%s\r\n") 
                % (*key )
                % (boost::format("%d") %num)
                % format_elapsed(ttl) 
                % format_elapsed(avg) 
                % format_elapsed(mean)
                % format_elapsed(stddev)
                ).str());


        }
        ret += (boost::format("%s\r\n") 
            % std::string(head.length(),'=') ).str();

        if( ClipboardAlso )
        {
            // dump header row of data block
            lines.push_back("");
            {
                std::string s;
                for( keyset::iterator key = keys.begin(); key != keys.end(); ++key )
                {
                    if( key != keys.begin() )
                        s.append("\t");
                    s.append(*key);
                }
                s.append("\r\n");
                lines.push_back(s);
            }

            // blow out the flat map of time values to a seperate vector of times for each key
            typedef std::map<std::string, std::vector<time_type> > nodematrix;
            nodematrix nodes;
            for( times::iterator time = TimeMap().begin(); time != TimeMap().end(); ++time )
                nodes[time->first].push_back(time->second);

            // dump each data point
            for( size_t row = 0; row < maxrows; ++row )
            {
                std::string rowDump;
                for( keyset::iterator key = keys.begin(); key != keys.end(); ++key )
                {
                    if( key != keys.begin() )
                        rowDump.append("\t");
                    if( nodes[*key].size() > row )
                        rowDump.append((
                        boost::format("%f") 
                        % nodes[*key][row]
                    ).str());
                }
                rowDump.append("\r\n");
                lines.push_back(rowDump);
            }

            // dump to the clipboard
            std::string dump;
            for( strings::iterator s = lines.begin(); s != lines.end(); ++s )
            {
                dump.append(*s);
            }

            OpenClipboard(0);
            EmptyClipboard();
            HGLOBAL hg = GlobalAlloc(GMEM_MOVEABLE, dump.length()+1);
            if( hg )
            {
                char* buf = (char*)GlobalLock(hg);
                if( buf )
                {
                    std::copy(dump.begin(), dump.end(), buf);
                    buf[dump.length()] = 0;
                }
                GlobalUnlock(hg);
                SetClipboardData(CF_TEXT, hg);
            }
            CloseClipboard();
        }

        return ret;
    }

    inline std::string Timer::format_elapsed(double d) 
    {
        if( d < 0.00000001 )
        {
            // show in ps with 4 digits
            return (boost::format("%0.4f ps") % (d * 1000000000000.0)).str();
        }
        if( d < 0.00001 )
        {
            // show in ns
            return (boost::format("%0.0f ns")% (d * 1000000000.0)).str();
        }
        if( d < 0.001 )
        {
            // show in us
            return (boost::format("%0.0f us") % (d * 1000000.0)).str();
        }
        if( d < 0.1 )
        {
            // show in ms
            return (boost::format("%0.0f ms") % (d * 1000.0)).str();
        }
        if( d <= 60.0 )
        {
            // show in seconds
            return (boost::format("%0.2f s") % d).str();
        }
        if( d < 3600.0 )
        {
            // show in min:sec
            return (boost::format("%01.0f:%02.2f") % floor(d/60.0) % fmod(d,60.0)).str();
        }
        // show in h:min:sec
        return (boost::format("%01.0f:%02.0f:%02.2f") % floor(d/3600.0) % floor(fmod(d,3600.0)/60.0) % fmod(d,60.0)).str();
    }

    inline void Timer::Reset()
    {
        TimeMap().clear();
    }

    inline __int64 Timer::TimerFreq()
    {
        static __int64 freq = 0;
        static bool init = false;
        if( !init )
        {
            LARGE_INTEGER li;
            QueryPerformanceFrequency(&li);
            freq = li.QuadPart;
            init = true;
        }
        return freq;
    }

    inline Timer::times& Timer::TimeMap()
    {
        static times times_;
        return times_;
    } 
};  // namespace dbg

- John Dibling

---

@Martin：不用谢，希望有所帮助。我忘了提到一个小细节。这个类可以做很多事情，但我几乎从来不用，只是想提一下。其中之一就是还可以将转储结果复制到Windows剪贴板中。这是“DumpTrials()”中默认的“false”参数。 - John Dibling

是的，我猜我们都做过这样的事情。然而，使用这种性能分析的问题在于由于慢操作（尤其是new()），这些分析代码会导致性能分析紧密模板代码时变得无用。而且，当创建这样重型的性能分析对象时，编译器会停止内联优化，从而导致结果完全不准确。 - Gene Bushuyev

@Gene：正如我所说，计时本身会改变结果。这个设备的目的不是告诉你某个代码块运行需要多长时间。无论如何，这样的设备都是毫无意义的，因为代码的运行时间会根据机器、其他进程、数据集等而有所增减，甚至还会受到CPU温度的影响。它的目的是为了给你一个相对于代码其他部分的执行时间估计值。出于这个目的，在各种代码中，它在我身上表现得很好。 - John Dibling

是的 - 我简化了它，只分配了一个固定大小为1024个事件的缓冲区，其中包含时间和固定长度的char[]消息标记。然后，时间戳调用非常便宜。 - Martin Beckett