// ========================================================================== // SeqAn - The Library for Sequence Analysis // ========================================================================== // Copyright (c) 2006-2018, Knut Reinert, FU Berlin // All rights reserved. // // Redistribution and use in source and binary forms, with or without // modification, are permitted provided that the following conditions are met: // // * Redistributions of source code must retain the above copyright // notice, this list of conditions and the following disclaimer. // * Redistributions in binary form must reproduce the above copyright // notice, this list of conditions and the following disclaimer in the // documentation and/or other materials provided with the distribution. // * Neither the name of Knut Reinert or the FU Berlin nor the names of // its contributors may be used to endorse or promote products derived // from this software without specific prior written permission. // // THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS" // AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE // IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE // ARE DISCLAIMED. IN NO EVENT SHALL KNUT REINERT OR THE FU BERLIN BE LIABLE // FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL // DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR // SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER // CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT // LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY // OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH // DAMAGE. // // ========================================================================== // Author: David Weese // ========================================================================== // Code for profiling. // ========================================================================== // TODO(holtgrew): This could use some cleanup. #include #include //SEQAN_NO_GENERATED_FORWARDS: no forwards are generated for this file #ifndef SEQAN_INCLUDE_SEQAN_BASIC_PROFILING_H_ #define SEQAN_INCLUDE_SEQAN_BASIC_PROFILING_H_ namespace seqan { // todo: substitute defines with inlines #ifndef SEQAN_PROFILE #define SEQAN_PROSET(i,v) do {} while (false) #define SEQAN_PROADD(i,v) do {} while (false) #define SEQAN_PROSUB(i,v) do {} while (false) #define SEQAN_PROVAL(i) 0 #define SEQAN_PROEXTRAS(i) do {} while (false) #define SEQAN_PROMARK(m) do {} while (false) #define SEQAN_PROENDMARK(m) do {} while (false) #define SEQAN_PRORESET do {} while (false) #define SEQAN_PROGETTIME 0 #define SEQAN_PROTIMESTART(a) do {} while (false) #define SEQAN_PROTIMEDIFF(a) 0 #define SEQAN_PROTIMEUPDATE(a) 0 // replace malloc and free in external tools // with SEQAN_PROMALLOC and SEQAN_PROFREE to profile // their memory usage #define SEQAN_PROMALLOC(s) malloc(s) #define SEQAN_PROFREE(p) free(p) #else #define SEQAN_PROSET(i,v) _profileSet(i,v) #define SEQAN_PROADD(i,v) _profileAdd(i,v) #define SEQAN_PROSUB(i,v) _profileSub(i,v) #define SEQAN_PROVAL(i) (ProfileData_<>::_proValue[i]) #define SEQAN_PROEXTRAS(i) {ProfileData_<>::_proExtraCount = i;} #define SEQAN_PROMARK(m) _profileMark(m) #define SEQAN_PROENDMARK(m) _profileEndMark(m) #define SEQAN_PRORESET _profileReset() #define SEQAN_PROGETTIME sysTime() #define SEQAN_PROTIMESTART(a) _proFloat a = sysTime() #define SEQAN_PROTIMEDIFF(a) (sysTime() - a) #define SEQAN_PROTIMEUPDATE(a) (_profileUpdate(a)) #define SEQAN_PROMALLOC(s) _profileMalloc(s) #define SEQAN_PROFREE(p) _profileFree(p) #endif #ifdef STDLIB_VS typedef int64_t ProfileInt_; //IOREV _notio_ #else typedef int64_t ProfileInt_; //IOREV _notio_ #endif typedef double _proFloat; typedef _proFloat ProfileTimeValue_; //IOREV _notio_ enum ProfileConstants_ { SEQAN_PROPAGESIZE = 4096, // B in byte SEQAN_PROFLOAT = 0, SEQAN_PROINT = 1, SEQAN_PROTIME = 2, SEQAN_PROTYPEMASK = 3, SEQAN_PROSTATE = 4 }; enum ProfileValueIndex_ { SEQAN_PROSYSTIME = 0, SEQAN_PROCPUTIME = 1, SEQAN_PROMEMORY = 2, // current memory usage (state value) SEQAN_PROIO = 3, // IOs done (measured in Blocks of size B) SEQAN_PROIORANDOM = 4, // IOs calls done (read/write calls done) SEQAN_PROIOVOLUME = 5, // current disk usage (state value) SEQAN_PRODEPTH = 6, // algorithmic rec. depth or loop count SEQAN_PROOPENFILES = 7, // currently opened files SEQAN_PROIWAIT = 8, // waiting time (initiating) SEQAN_PROCWAIT = 9, // waiting time (completing) SEQAN_PROEXTRA1 = 10, SEQAN_PROEXTRA2 = 11, SEQAN_PROEXTRA3 = 12, SEQAN_PROINDEXCOUNT = 13, SEQAN_PROEXTRACOUNT = 3 }; const char ProfileValueType_[] = { SEQAN_PROTIME, SEQAN_PROTIME, SEQAN_PROINT + SEQAN_PROSTATE, SEQAN_PROINT, SEQAN_PROINT, SEQAN_PROINT + SEQAN_PROSTATE, SEQAN_PROINT + SEQAN_PROSTATE, SEQAN_PROINT + SEQAN_PROSTATE, SEQAN_PROFLOAT, SEQAN_PROFLOAT, SEQAN_PROFLOAT + SEQAN_PROSTATE, SEQAN_PROFLOAT + SEQAN_PROSTATE, SEQAN_PROFLOAT + SEQAN_PROSTATE }; typedef ProfileTimeValue_ ProfileTStates_[SEQAN_PROINDEXCOUNT]; //IOREV _notio_ typedef _proFloat ProfileTTimes[SEQAN_PROINDEXCOUNT]; //IOREV _notio_ struct ProfileFile_; //IOREV template struct ProfileData_ { //IOREV _notio_ static ProfileTStates_ _proValue; static ProfileTTimes _proLastUpdate; static int _proExtraCount; static clock_t _proCpuTimeLast; // clock_t wraps around every 72mins static ProfileInt_ _proCpuTimeOffset; // we have to work around this static ProfileFile_* _proPFile; static ProfileFile_* _proPFileStream; }; template ProfileTStates_ ProfileData_::_proValue = {}; template ProfileTStates_ ProfileData_::_proLastUpdate = {}; template int ProfileData_::_proExtraCount = 0; template clock_t ProfileData_::_proCpuTimeLast = 0; template ProfileInt_ ProfileData_::_proCpuTimeOffset = 0; template ProfileFile_* ProfileData_::_proPFile = NULL; template ProfileFile_* ProfileData_::_proPFileStream = NULL; inline ProfileFile_* & _proPFile() { return ProfileData_<>::_proPFile; } //IOREV inline ProfileFile_* & _proPFileStream() { return ProfileData_<>::_proPFileStream; } //IOREV /*! * @fn cpuTime * @headerfile * @brief Returns the cpu time in seconds. * * @signature double cpuTime(); * * @return double CPU time stamp in seconds. * * Calls clock to retrieve the processor time used by the running thread. This implies that the thread's * processor time does not tick if the thread is suspended. While this has its advantages, benchmarks should generally * focus on wall clock time, not processor time. Wall clock time is returned by sysTime. * * @see sysTime */ // HINT: The unit of all time functions is second. inline _proFloat cpuTime() { clock_t now = clock(); if (ProfileData_<>::_proCpuTimeLast > now) { // test for time wrap ProfileData_<>::_proCpuTimeOffset += (~0u); // got one ProfileData_<>::_proCpuTimeOffset ++; // printf("\n!!WRAP!! old:%d, now:%d ofs:%d\n",ProfileData_<>::_proCpuTimeLast,now,ProfileData_<>::_proCpuTimeOffset); } ProfileData_<>::_proCpuTimeLast = now; return (ProfileData_<>::_proCpuTimeOffset + now) / (_proFloat)CLOCKS_PER_SEC; } /*! * @fn sysTime * @headerfile * @brief Returns the system time in seconds. * * @signature double sysTime(); * * @return double A double, system time stamp in seconds. Types: nolink:double * * In contrast to @link cpuTime @endlink, the system time corresponds to the wall clock time under Linux and Mac OS X. * Under Windows sysTime returns the result of cpuTime. * * Use this for benchmarking uner Linux and Mac Os X. * * Calls clock_gettime under Linux and gettimeofday under Mac OS X. * * @section Examples * * We can use sysTime to instrument our code for profiling/timing information quite robustly. The following demonstrates * how the Function.sysTime is used in many SeqAn apps for collecting timing information. * * @code{.cpp} * bool printTiming = true; * * // ... * * double startTime = sysTime(); * // Do some complex calculation. * if (printTiming) * std::cerr << "Some complex calculation too " << sysTime() - startTime << " s." << std::endl; * @endcode * * @see cpuTime */ inline _proFloat sysTime() { return static_cast<_proFloat>(std::chrono::system_clock::now().time_since_epoch() / std::chrono::duration<_proFloat>(1)); } struct ProfileFile_ { //IOREV not generic, uses FILE* instead of File() and custom IO FILE *out; bool running; _proFloat dumpStep; // 0 .. manual dump mode, >0 .. live stream _proFloat dumpNext; ProfileTStates_ all, last; std::string mark; unsigned lines; ProfileFile_() { running = false; } ProfileFile_(char const *fname, _proFloat _dumpStep = 300.0) { // five minutes default dump interval running = false; start(fname, _dumpStep); } ~ProfileFile_() { if (running) stop(); } inline void start(char const *fname, _proFloat _dumpStep = 300.0, bool append = false) { if (append) out = fopen(fname, "a"); else { out = fopen(fname, "w"); dumpHeader(); } if (!out) printf("WARNING: proFile could not be opened.\n"); setTime(ProfileData_<>::_proValue); syncAll(all); syncAll(last); running = true; lines = 0; dumpStep = _dumpStep; dumpNext = sysTime(); dump(last); } inline void stop() { dump(last); maximize(all, last); if (dumpStep == 0) { mark = "Zusammenfassung"; dump(all); } fclose(out); running = false; } inline void syncTime(ProfileTStates_ &dst) { std::memcpy(dst, ProfileData_<>::_proValue, 2 * sizeof(ProfileTimeValue_)); } inline void sync(ProfileTStates_ &dst) { std::memcpy(&(dst[2]), &(ProfileData_<>::_proValue[2]), sizeof(ProfileTStates_) - 2 * sizeof(ProfileTimeValue_)); } inline void syncAll(ProfileTStates_ &dst) { std::memcpy(dst, ProfileData_<>::_proValue, sizeof(ProfileTStates_)); } inline static void setTime(ProfileTStates_ &dst) { dst[0] = sysTime(); dst[1] = cpuTime(); } inline void maximize(ProfileTStates_ &dst, ProfileTStates_ const &src) { for(int i = 0; i < SEQAN_PROINDEXCOUNT; ++i) if (((ProfileValueType_[i] & SEQAN_PROSTATE) != 0)) if (dst[i] < src[i]) dst[i] = src[i]; } inline void dumpTab() { if (!bol) fprintf(out, " \t"); bol = false; } inline void dumpEndl() { fprintf(out, "\n"); } inline void dumpHeader() { fprintf(out, "\"Echtzeit\"\t\"CPU-Zeit\"\t\"Speicher\"\t\"I/O-Zugriffe\"\t\"wahlfreie I/Os\"\t\"I/O-Volumen\"\t\"Rekursionstiefe\"\t\"Offene Dateien\"\t\"Idle-Zeit vor I/O\"\t\"Idle-Zeit nach I/O\"\n"); } inline void dumpTime(_proFloat seconds) { if (seconds < 0) { fputc('-', out); seconds = -seconds; } int secs = (int)seconds; int mins = secs/60; secs -= 60*mins; int hours = mins/60; mins -= 60*hours; fprintf(out, "%d:%02d:%02d", hours, mins, secs); } inline void dumpTimeEx(_proFloat seconds) { int milli = (int)(seconds * 1000.0); int secs = (int)seconds; int mins = secs/60; secs -= 60*mins; int hours = mins/60; mins -= 60*hours; fprintf(out, "%d:%02d:%02d.%03d", hours, mins, secs, milli); } inline void dumpValue(ProfileTStates_ &stat, int valNum) { _proFloat f = stat[valNum]; if ((ProfileValueType_[valNum] & SEQAN_PROSTATE) == 0) f = ProfileData_<>::_proValue[valNum] - f; switch (ProfileValueType_[valNum] & SEQAN_PROTYPEMASK) { case SEQAN_PROINT: // state value -> print last seen maximum fprintf(out, "%.0f", f); break; case SEQAN_PROFLOAT: fprintf(out, "%f", f); break; case SEQAN_PROTIME: dumpTimeEx(f); } } inline void dumpSysValues(ProfileTStates_ &stat) { for(int i = 0; i < SEQAN_PROINDEXCOUNT - SEQAN_PROEXTRACOUNT; ++i) { dumpTab(); dumpValue(stat, i); } } inline void dumpExtraValues(ProfileTStates_ &stat) { for(int i = 0; i < ProfileData_<>::_proExtraCount; ++i) { dumpTab(); dumpValue(stat, SEQAN_PROINDEXCOUNT - SEQAN_PROEXTRACOUNT + i); } } inline void dumpMark() { if (!mark.empty()) { dumpTab(); fprintf(out, "\"%s\"", mark.c_str()); mark.erase(); } } inline void dump(ProfileTStates_ &stat) { setTime(ProfileData_<>::_proValue); dumpNext += dumpStep; bol = true; bool _flush = ((dumpStep == 0.0)) || ((lines & 16) == 0); dumpSysValues(stat); dumpExtraValues(stat); dumpMark(); dumpEndl(); if (_flush) fflush(out); ++lines; } inline void signalDumpTest(_proFloat now) { if (dumpStep > 0 && now > dumpNext && running) { dump(last); maximize(all, last); sync(last); } } inline void signalNewMax(int valNum) { if (running) if (last[valNum] < ProfileData_<>::_proValue[valNum]) last[valNum] = ProfileData_<>::_proValue[valNum]; } inline void setMark(const char *text) { if (running) { mark = text; if (dumpStep == 0.0) { dump(last); // manual dump; maximize(all, last); sync(last); } } } inline void reset() { syncTime(last); } inline void setEndMark(const char *text) { if (running) { setMark(text); reset(); } } private: bool bol; // begin of line }; /* inline void _profileSignalDumpTest(_proFloat now); inline void _profileSignalNewMax(int valNum); inline void _profileMark(const char *text); inline void _profileEndMark(const char *text); inline void _profileReset(); inline void _profileSet(int valNum, _proFloat value); inline void _profileAdd(int valNum, _proFloat value); inline void _profileSub(int valNum, _proFloat value); // simple interface for external programs inline void *_profileMalloc(size_t size); inline void _profileFree(void *_ptr); */ inline void _profileSignalDumpTest(_proFloat now) { //IOREV _notio_ if (ProfileData_<>::_proPFileStream) ProfileData_<>::_proPFileStream->signalDumpTest(now); } inline void _profileSignalNewMax(int valNum) { //IOREV _notio_ if (((ProfileValueType_[valNum] & SEQAN_PROSTATE) != 0)) { if (ProfileData_<>::_proPFileStream) ProfileData_<>::_proPFileStream->signalNewMax(valNum); if (ProfileData_<>::_proPFile) ProfileData_<>::_proPFile->signalNewMax(valNum); } } inline void _profileMark(const char *text) { //IOREV _notio_ if (ProfileData_<>::_proPFileStream) ProfileData_<>::_proPFileStream->setMark(text); if (ProfileData_<>::_proPFile) ProfileData_<>::_proPFile->setMark(text); } inline void _profileEndMark(const char *text) { //IOREV _notio_ if (ProfileData_<>::_proPFileStream) { ProfileData_<>::_proPFileStream->setEndMark(text); } if (ProfileData_<>::_proPFile) { ProfileData_<>::_proPFile->setEndMark(text); } } inline void _profileReset() { //IOREV _notio_ if (ProfileData_<>::_proPFileStream) { ProfileData_<>::_proPFileStream->reset(); } if (ProfileData_<>::_proPFile) { ProfileData_<>::_proPFile->reset(); } } template inline void _profileSet(ProfileValueIndex_ valNum, TValue value) { //IOREV _notio_ _proFloat now = sysTime(); ProfileData_<>::_proLastUpdate[valNum] = now; if (ProfileData_<>::_proValue[valNum] < value) { ProfileData_<>::_proValue[valNum] = value; _profileSignalNewMax(valNum); } else ProfileData_<>::_proValue[valNum] = value; _profileSignalDumpTest(now); } template inline void _profileAdd(ProfileValueIndex_ valNum, TValue value) { //IOREV _notio_ _proFloat now = sysTime(); ProfileData_<>::_proValue[valNum] += value; ProfileData_<>::_proLastUpdate[valNum] = now; if (valNum == SEQAN_PROIO) _profileAdd(SEQAN_PROIORANDOM, 1); _profileSignalNewMax(valNum); _profileSignalDumpTest(now); } template inline void _profileSub(ProfileValueIndex_ valNum, TValue value) { //IOREV _notio_ _proFloat now = sysTime(); ProfileData_<>::_proValue[valNum] -= value; ProfileData_<>::_proLastUpdate[valNum] = now; _profileSignalDumpTest(now); } // simple interface for external programs inline void *_profileMalloc(size_t size) { //IOREV _notio_ size_t *ptr = reinterpret_cast(malloc(size + sizeof(size_t))); if (ptr) { _profileAdd(SEQAN_PROMEMORY, (_proFloat)(*ptr = size)); // printf("_profileMalloc %x size %d\n", ptr, size); ++ptr; } return ptr; } inline void _profileFree(void *_ptr) { //IOREV _notio_ size_t *ptr = reinterpret_cast(_ptr); if (ptr) { --ptr; // printf("_profileFree %x size %d\n", _ptr, *ptr); _profileSub(SEQAN_PROMEMORY, (_proFloat)*ptr); } free(ptr); } inline _proFloat _profileUpdate(_proFloat& a) { //IOREV _notio_ _proFloat x = sysTime() - a; a += x; return x; } } #endif // #ifndef SEQAN_INCLUDE_SEQAN_BASIC_PROFILING_H_