include/dlvhex2/Benchmarking.h

Go to the documentation of this file.

/* dlvhex -- Answer-Set Programming with external interfaces.
 * Copyright (C) 2005-2007 Roman Schindlauer
 * Copyright (C) 2006-2015 Thomas Krennwallner
 * Copyright (C) 2009-2016 Peter Schüller
 * Copyright (C) 2011-2016 Christoph Redl
 * Copyright (C) 2015-2016 Tobias Kaminski
 * Copyright (C) 2015-2016 Antonius Weinzierl
 *
 * This file is part of dlvhex.
 *
 * dlvhex is free software; you can redistribute it and/or modify it
 * under the terms of the GNU Lesser General Public License as
 * published by the Free Software Foundation; either version 2.1 of
 * the License, or (at your option) any later version.
 *
 * dlvhex is distributed in the hope that it will be useful, but
 * WITHOUT ANY WARRANTY; without even the implied warranty of
 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
 * Lesser General Public License for more details.
 *
 * You should have received a copy of the GNU Lesser General Public
 * License along with dlvhex; if not, write to the Free Software
 * Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA
 * 02110-1301 USA.
 */

#ifndef DLVHEX_H_BENCHMARKING_INCLUDED_1555
#define DLVHEX_H_BENCHMARKING_INCLUDED_1555

#include "dlvhex2/PlatformDefinitions.h"

#include <boost/scope_exit.hpp>
                                 // seems to be required for scope_exit
#include <boost/typeof/typeof.hpp>
#include <boost/date_time/posix_time/posix_time.hpp>
#include <boost/thread/mutex.hpp>
#include <vector>
#include <ostream>

// Benchmarking is always compiled into dlvhex,
// but benchmarking of dlvhex itself is only
// activated if you configure with --enable-debug
//
// Plugins can use benchmarking of dlvhex by doing
// #define DLVHEX_BENCHMARK
// #include <dlvhex2/Benchmarking.h>
// in a .cpp file that wants to use benchmarking.
//
// usage example:
//
// DLVHEX_BENCHMARK_REGISTER(sid1,"calling dlv");
// DLVHEX_BENCHMARK_REGISTER(sid2,"fork+exec dlv");
// DLVHEX_BENCHMARK_REGISTER(sid3,"parse dlv result");
//
// DLVHEX_BENCHMARK_START(sid1)
//   DLVHEX_BENCHMARK_START(sid2)
//   // fork and exec
//   DLVHEX_BENCHMARK_STOP(sid2)
//
//   {
//      DLVHEX_BENCHMARK_SCOPE(sid3)
//      parse result
//      ...
//   }
// DLVHEX_BENCHMARK_STOP(sid1)
// DLVHEX_BENCHMARK_COUNT(sid4,someinteger)
// DLVHEX_BENCHMARK_REGISTER_AND_START(sid6,"reg start")
// {
//   DLVHEX_BENCHMARK_REGISTER_AND_SCOPE(sid5,"reg scope")
//   ...
// }
// DLVHEX_BENCHMARK_STOP(sid6)
//
// if you want to have a benchmark scope within a template, you need to use
// DLVHEX_BENCHMARK_REGISTER_AND_SCOPE_TPL(sid7,"reg scope in template")
//
// you can also manage the stat IDs yourself
// (e.g., for creating one instrumentation per custom external atom,
//  not only one for some base class)
// #if defined(DLVHEX_BENCHMARK)
//   dlvhex::benchmark::ID myStoredSid =
//     dlvhex::benchmark::BenchmarkController::Instance().getInstrumentationID("my message");
// #endif
//
// invalidate(sid) and INVALIDATE is used to abort instrumentations that were started but should not be counted
// (e.g., if there is no model, we will not have a time to first model)
// invalidating a non-running counter does nothing
//
// there are two benchmark controllers that can be used:
// * simple: (#define DLVHEX_BENCHMARK_SIMPLE)
//   + fast and simple
//   - counts overlapping instrumentalizations twice
//     (not if they have the same name)
//   - gives less intuitive timing results
// * nesting-aware: (#define DLVHEX_BENCHMARK_NESTINGAWARE)
//   - a bit more complex
//   + counts "pure" time where an instrumentalization
//     was the last activated one (uses a stack of instrumentalizations)
//   + gives more intuitive timing results

//#define DLVHEX_BENCHMARK_SIMPLE
#define DLVHEX_BENCHMARK_NESTINGAWARE

#if defined(DLVHEX_BENCHMARK)
# define DLVHEX_BENCHMARK_REGISTER(sid,msg) \
    static DLVHEX_NAMESPACE benchmark::ID sid = DLVHEX_NAMESPACE benchmark::BenchmarkController::Instance().getInstrumentationID(msg)
# define DLVHEX_BENCHMARK_START(sid) \
    DLVHEX_NAMESPACE benchmark::BenchmarkController::Instance().start(sid)
# define DLVHEX_BENCHMARK_STOP(sid) \
    DLVHEX_NAMESPACE benchmark::BenchmarkController::Instance().stop(sid)
# define DLVHEX_BENCHMARK_INVALIDATE(sid) \
    DLVHEX_NAMESPACE benchmark::BenchmarkController::Instance().invalidate(sid)
# define DLVHEX_BENCHMARK_SUSPEND(sid) \
    DLVHEX_NAMESPACE benchmark::BenchmarkController::Instance().stop(sid,false)
# define DLVHEX_BENCHMARK_COUNT(sid,num) \
    DLVHEX_NAMESPACE benchmark::BenchmarkController::Instance().count(sid,num)
# define DLVHEX_BENCHMARK_SCOPE(sid) \
    DLVHEX_NAMESPACE benchmark::BenchmarkController::Instance().start(sid); \
    BOOST_SCOPE_EXIT( (sid) ) \
    { \
        DLVHEX_NAMESPACE benchmark::BenchmarkController::Instance().stop(sid); \
    } BOOST_SCOPE_EXIT_END
# define DLVHEX_BENCHMARK_SUSPEND_SCOPE(sid) \
    DLVHEX_NAMESPACE benchmark::BenchmarkController::Instance().stop(sid,false); \
    BOOST_SCOPE_EXIT( (sid) ) \
    { \
        DLVHEX_NAMESPACE benchmark::BenchmarkController::Instance().start(sid); \
    } BOOST_SCOPE_EXIT_END
# define DLVHEX_BENCHMARK_SCOPE_TPL(sid) \
    DLVHEX_NAMESPACE benchmark::BenchmarkController::Instance().start(sid); \
    BOOST_SCOPE_EXIT_TPL( (sid) ) \
    { \
        DLVHEX_NAMESPACE benchmark::BenchmarkController::Instance().stop(sid); \
    } BOOST_SCOPE_EXIT_END
# define DLVHEX_BENCHMARK_REGISTER_AND_SCOPE(sid,msg) \
    DLVHEX_BENCHMARK_REGISTER(sid,msg); DLVHEX_BENCHMARK_SCOPE(sid);
# define DLVHEX_BENCHMARK_REGISTER_AND_SCOPE_TPL(sid,msg) \
    DLVHEX_BENCHMARK_REGISTER(sid,msg); DLVHEX_BENCHMARK_SCOPE_TPL(sid);
# define DLVHEX_BENCHMARK_REGISTER_AND_START(sid,msg) \
    DLVHEX_BENCHMARK_REGISTER(sid,msg); DLVHEX_BENCHMARK_START(sid);
# define DLVHEX_BENCHMARK_REGISTER_AND_COUNT(sid,msg,num) \
    DLVHEX_BENCHMARK_REGISTER(sid,msg); DLVHEX_BENCHMARK_COUNT(sid,num);
#else
# define DLVHEX_BENCHMARK_REGISTER(sid,msg)               do { } while(0)
# define DLVHEX_BENCHMARK_START(sid)                      do { } while(0)
# define DLVHEX_BENCHMARK_STOP(sid)                       do { } while(0)
# define DLVHEX_BENCHMARK_INVALIDATE(sid)                 do { } while(0)
# define DLVHEX_BENCHMARK_SUSPEND(sid)                    do { } while(0)
# define DLVHEX_BENCHMARK_SUSPEND_SCOPE(sid)              do { } while(0)
# define DLVHEX_BENCHMARK_COUNT(sid,num)                  do { } while(0)
# define DLVHEX_BENCHMARK_SCOPE(sid)                      do { } while(0)
# define DLVHEX_BENCHMARK_SCOPE_TPL(sid)                  do { } while(0)
# define DLVHEX_BENCHMARK_REGISTER_AND_SCOPE(sid,msg)     do { } while(0)
# define DLVHEX_BENCHMARK_REGISTER_AND_SCOPE_TPL(sid,msg) do { } while(0)
# define DLVHEX_BENCHMARK_REGISTER_AND_START(sid,msg)     do { } while(0)
# define DLVHEX_BENCHMARK_REGISTER_AND_COUNT(sid,msg,num) do { } while(0)
#endif                           // defined(DLVHEX_BENCHMARK)

DLVHEX_NAMESPACE_BEGIN

namespace benchmark
{

    typedef unsigned ID;
    typedef unsigned Count;
    typedef boost::posix_time::ptime Time;
    typedef boost::posix_time::time_duration Duration;

    namespace simple
    {

        class DLVHEX_EXPORT BenchmarkController
        {
            public:
                struct Stat
                {
                    std::string name;
                    Count count;
                    Count level;
                    Count prints;
                    Time start;
                    Duration duration;
                    bool running;

                    Stat(const std::string& name);
                };

            public:
                inline std::ostream& printInSecs(std::ostream& o, const Duration& d, int width=0) const;

                // comfort formatting
                std::string count(const std::string& identifier, int width=0) const;
                std::string duration(const std::string& identifier, int width=0) const;

                                 // inline for performance
                inline void printInformation(const Stat& st);
                inline void printInformationContinous(
                                 // inline for performance
                    Stat& st, const Duration& dur);

            public:
                //
                static BenchmarkController& Instance();

                static void finish();

                ~BenchmarkController();

                //
                // configure
                //

                void setOutput(std::ostream* o);
                void setPrintInterval(Count skip);

                //
                // instrumentation points
                //

                ID getInstrumentationID(const std::string& name);
                                 // inline for performance
                inline std::ostream& printCount(std::ostream& out, ID id);
                                 // inline for performance
                inline std::ostream& printDuration(std::ostream& out, ID id);
                inline const Stat& getStat(ID id) const { return instrumentations[id]; }

                //
                // record measured things
                //

                // stop and resume benchmarking
                void suspend();
                void resume();

                // start timer
                                 // inline for performance
                inline void start(ID id);
                                 // inline for performance
                inline void stop(ID id, bool count=true);
                                 // inline for performance
                inline void count(ID id, Count increment=1);
                void invalidate(ID id);

                void snapshot(ID id, ID intoID);

                void snapshot(const std::string& fromstr, const std::string& tostr);

            private:
                BenchmarkController();

                ID myID;
                ID maxID;
                std::vector<Stat> instrumentations;
                std::map<std::string, ID> name2id;

                std::ostream* output;
                Count printSkip;

                boost::mutex mutex;
                unsigned sus;
        };

        //inline
        std::ostream& BenchmarkController::printInSecs(std::ostream& out, const Duration& td, int width) const
        {
            long in_secs = (long)td.total_milliseconds();

            long secs = in_secs / 1000;
            long rest = in_secs % 1000;

            out << std::setw(width) << secs << ".";

            if (rest < 10) {
                out << "00";
            }
            else if (rest < 100) {
                out << "0";
            }

            return out << rest;
        }

        // print information about stat
        // inline for performance
        void BenchmarkController::printInformation(const Stat& st) {
            if( output ) {
                (*output) <<
                    "BM:" << std::setw(30) << st.name <<
                    ": count:" << std::setw(8) << st.count;
                (*output) <<
                    " total:";
                printInSecs(*output, st.duration, 4) <<
                    "s avg:";
                if( st.count > 0 ) {
                    printInSecs(*output, st.duration/st.count, 4);
                }
                else {
                    (*output) << "   -.---";
                }
                (*output) << std::endl;
            }
        }

        // print only count of ID
        std::ostream& BenchmarkController::printCount(std::ostream& out, ID id) {
            boost::mutex::scoped_lock lock(mutex);
            Stat& st = instrumentations[id];
            return out << st.count;
        }

        std::ostream& BenchmarkController::printDuration(std::ostream& out, ID id) {
            boost::mutex::scoped_lock lock(mutex);
            Stat& st = instrumentations[id];
            return printInSecs(out, st.duration);
        }

        // print continuous information about stat
        // inline for performance
        void BenchmarkController::printInformationContinous(Stat& st, const Duration& dur) {
            if( st.prints >= printSkip ) {
                st.prints = 0;
                if( output ) {
                    (*output) <<
                        "BM:" << std::setw(30) << st.name <<
                        ": count:" << std::setw(8) << st.count <<
                        " total:";
                    printInSecs(*output, st.duration, 4) << "s" <<
                        " last:";
                    printInSecs(*output, dur, 2) << "s" << ((st.running)?"(runs)":"") << std::endl;
                }
            }
            else {
                st.prints++;
            }
        }

        // inline for performance
        // start timer
        void BenchmarkController::start(ID id) {
            if (sus) return;
            boost::mutex::scoped_lock lock(mutex);
            Stat& st = instrumentations[id];
            if( !st.running ) {
                st.start = boost::posix_time::microsec_clock::local_time();
                st.running = true;
                // running once -> level 1
                st.level = 1;
            }
            else {
                // increase nesting level
                st.level++;
            }
        }

        // inline for performance
        // stop and record elapsed time, print stats
        void BenchmarkController::stop(ID id, bool count) {
            if (sus) return;
            boost::mutex::scoped_lock lock(mutex);
            Stat& st = instrumentations[id];

            if( st.running && st.level == 1 ) {
                Duration dur = boost::posix_time::microsec_clock::local_time() - st.start;
                st.duration += dur;
                st.running = false;
                if( count ) {
                    st.count++;
                    printInformationContinous(st,dur);
                }
            }
            else if( st.running ) {
                // decrease nesting level
                st.level--;
            }
        }

        // record count (no time), print stats
        // inline for performance
        void BenchmarkController::count(ID id, Count increment) {
            if (sus) return;
            boost::mutex::scoped_lock lock(mutex);
            Stat& s = instrumentations[id];
            s.count += increment;
            // only count how often we count, otherwise we might spam
            s.prints ++;
            printInformationContinous(s,Duration());
        }

    }                            // namespace simple

    namespace nestingAware
    {

        class DLVHEX_EXPORT NestingAwareController
        {
            public:
                struct Stat
                {
                    std::string name;
                    Count count;
                    Duration duration;
                    Duration pureDuration;
                    Count level;
                    Time nextPrint;

                    Stat(const std::string& name, Duration printInterval);
                };
                struct Current
                {
                    ID which;
                    Time firststart;
                    Time start;

                    Current(ID which);
                };

            public:
                inline std::ostream& printInSecs(std::ostream& o, const Duration& d, int width=0) const;

                // comfort formatting
                std::string count(const std::string& identifier, int width=0) const;
                std::string duration(const std::string& identifier, int width=0) const;

                void printInformation(const Stat& st);
                inline void printInformationContinous(Stat& st, const Duration& dur);

            public:
                //
                static NestingAwareController& Instance();

                static void finish();

                ~NestingAwareController();

                //
                // configure
                //

                void setOutput(std::ostream* o);
                void setPrintInterval(Count skip);

                //
                // instrumentation points
                //

                ID getInstrumentationID(const std::string& name);
                                 // inline for performance
                inline std::ostream& printCount(std::ostream& out, ID id);
                                 // inline for performance
                inline std::ostream& printDuration(std::ostream& out, ID id);
                inline const Stat& getStat(ID id) const { return instrumentations[id]; }

                //
                // record measured things
                //

                // stop and resume benchmarking
                void suspend();
                void resume();

                // start timer
                                 // inline for performance
                inline void start(ID id);
                                 // inline for performance
                inline void stop(ID id, bool count=true);
                                 // inline for performance
                inline void count(ID id, Count increment=1);
                void invalidate(ID id);

                void snapshot(ID id, ID intoID);

                void snapshot(const std::string& fromstr, const std::string& tostr);

            private:
                NestingAwareController();

                ID myID;
                ID maxID;
                std::vector<Stat> instrumentations;
                std::map<std::string, ID> name2id;
                std::vector<Current> current;

                Duration printInterval;
                std::ostream* output;

                boost::mutex mutex;
                unsigned sus;
        };

        //inline
        std::ostream& NestingAwareController::printInSecs(std::ostream& out, const Duration& td, int width) const
        {
            long in_secs = (long)td.total_milliseconds();

            long secs = in_secs / 1000;
            long rest = in_secs % 1000;

            out << std::setw(width) << secs << ".";

            if (rest < 10) {
                out << "00";
            }
            else if (rest < 100) {
                out << "0";
            }

            return out << rest;
        }

        // print only count of ID
        std::ostream& NestingAwareController::printCount(std::ostream& out, ID id) {
            boost::mutex::scoped_lock lock(mutex);
            Stat& st = instrumentations[id];
            return out << st.count;
        }

        std::ostream& NestingAwareController::printDuration(std::ostream& out, ID id) {
            boost::mutex::scoped_lock lock(mutex);
            Stat& st = instrumentations[id];
            return printInSecs(out, st.duration);
        }

        // print continuous information about stat
        // inline for performance
        void NestingAwareController::printInformationContinous(Stat& st, const Duration& dur) {
            if( !output )
                return;
            Time now = boost::posix_time::microsec_clock::local_time();
            if( now > st.nextPrint ) {
                st.nextPrint = now + printInterval;
                (*output) <<
                    "BM:" << std::setw(30) << st.name <<
                    ": count:" << std::setw(8) << st.count <<
                    " total:";
                printInSecs(*output, st.duration, 4) << "s" <<
                    " pure:";
                printInSecs(*output, st.pureDuration, 4) << "s" <<
                    " last:";
                printInSecs(*output, dur, 2) << "s" << std::endl;
            }
        }

        // inline for performance
        // start timer
        void NestingAwareController::start(ID id) {
            boost::mutex::scoped_lock lock(mutex);
            Stat& st = instrumentations[id];

            Time now = boost::posix_time::microsec_clock::local_time();

            st.level++;          // not running = 0, 1 = not nested
            if( !current.empty() ) {
                // suspend previously active instrumentation (and record pure time elapsed)
                Current& prevc = current.back();
                Stat& prevst = instrumentations[prevc.which];
                prevst.pureDuration += now - prevc.start;
            }

            // start new instrumentation
            current.push_back(Current(id));
            Current& c = current.back();
            c.firststart = now;
            c.start = now;
        }

        // inline for performance
        // stop and record elapsed time, print stats
        void NestingAwareController::stop(ID id, bool count) {
            boost::mutex::scoped_lock lock(mutex);
            Stat& st = instrumentations[id];

            Time now = boost::posix_time::microsec_clock::local_time();

            // currently active instrumentation
            Current& c = current.back();
            if( id != c.which )
                // warn but ignore
                std::cerr << "inconsistency: instrumentation '" << st.name <<
                    "' currently running but got stop() for '" << instrumentations[id].name <<
                    "'! (might cause subsequent errors)" << std::endl;

            // update pure duration
            st.pureDuration += now - c.start;

            // update overall duration, but only if not nested with itself
            // (this way neither pure nor overall duration is counted twice)
            Duration thisDuration;
            if( st.level == 1 ) {
                // the continuously logged duration must be non-pure, otherwise we need
                // to separately accumulate pureDuration since most recent start()
                thisDuration = now - c.firststart;
                st.duration += thisDuration;
            }
            if( count ) {
                st.count++;
                printInformationContinous(st, thisDuration);
            }

            // remove current instrumentation
            current.pop_back();
            st.level--;

            // leave function if there is no higher-level instrumentation running
            if( current.empty() )
                return;

            // resume previous instrumentation
            Current& prevc = current.back();
            prevc.start = now;
        }

        // record count (no time), print stats
        // inline for performance
        void NestingAwareController::count(ID id, Count increment) {
            boost::mutex::scoped_lock lock(mutex);
            Stat& s = instrumentations[id];
            s.count += increment;
            printInformationContinous(s,Duration());
        }

    }                            // namespace nestingAware

    #if defined(DLVHEX_BENCHMARK_SIMPLE)
    typedef simple::BenchmarkController BenchmarkController;
    #elif defined(DLVHEX_BENCHMARK_NESTINGAWARE)
    typedef nestingAware::NestingAwareController BenchmarkController;
    #else
    # error Benchmarking is defined but neither SIMPLE nor NESTINGAWARE is chosen!
    #endif

}                                // namespace benchmark


DLVHEX_NAMESPACE_END
#endif                           // DLVHEX_H_BENCHMARKING_INCLUDED_1555


// vim:expandtab:ts=4:sw=4:
// mode: C++
// End: