[Boost.tracer] library request
[Boost.tracer] library request is founded on a desire to trace some statistics about program execution. The sample program below demonstrates these statistics. Sample program file: ******** START OF FILE ******** #include <tracer.h> void foo() { TRACE_LIFETIME; usleep(rand() % 100000); } int main() { TRACE_LIFETIME; for(int i = 0; i < 100; ++i) foo(); } ******** END OF FILE ******** Produced log file: ******** START OF FILE ******** All the program time: 05265686 us (micro secs) TRACE POINT: Function: int main() Calls: 0000000001 times Average T between calls: 0000000000 us Average life T: 0005264459 us File: main.cpp Line: 00000009 TRACE POINT: Function: void foo() Calls: 0000000100 times Average T between calls: 0000051665 us Average life T: 0000052606 us File: main.cpp Line: 00000004 ******** END OF FILE ******** Comment: TRACE_LIFETIME is a MACRO that traces some scope statistics, namely: "Function" - the function name where the scope is; "Calls" - number of entries into this scope; "Average T between calls" - average time period between "Calls"; "Average life T" - average time spent in this scope. Conclusion: I think it is reasonable to introduce this trace functionality into (for example) boost::tracer namespace. I had wrote tracer.h and tracer.cpp source files and I wish Boost community to consider them. Thank You.
Hi, Boost.Chrono provide already this functionality with its new feature Stopwatch. See http://old.nabble.com/-chrono--v0.3--New-Stopwatch-Feature-tt27202338.html. Stopwatch is a an generic feature that allows the user to trace all you trace and more expect your "Average T between calls". stopclock<> provides a run time reporting package that can be invoked in a single line of code to report the usage of a Clock. stopclock_accumulator<> associates an accumulator with a stopwatch, so we are able to retrieve any statistical feature Boost.Accumulator provides. For example: . ******** START OF FILE ******** #include <boost/stopwatches.h> #include <cmath> #define TRACE_LIFETIME \ static boost::chrono::stopclock_accumulator<> acc(BOOST_CHRONO_ACCUMULATOR_FUNCTION_FORMAT); \ boost::chrono::stopclock_accumulator<>::scoped_run _(acc); int f1(long j) { TRACE_LIFETIME; for ( long i = 0; i < j; ++i ) std::sqrt( 123.456L ); // burn some time return 0; } int main() { TRACE_LIFETIME; f1(100000); f1(200000); f1(300000); return 0; } ******** END OF FILE ******** produce the output int f1(long int) : 3 times, sum=0.031s, min=0.006s, max=0.013s, mean=0.010s int main() : 1 times, sum=0.031s, min=0.031s, max=0.031s, mean=0.031s I'm interesteed in seen your code, could you upload it somewhere? Any comments on the Stopwatch part of the Chrono library is welcome. Best, Vicente ----- Original Message ----- From: "Andrew Chinkoff" <achinkoff@gmail.com> To: <boost@lists.boost.org> Sent: Wednesday, January 20, 2010 12:47 AM Subject: [boost] [Boost.tracer] library request
[Boost.tracer] library request is founded on a desire to trace some statistics about program execution.
The sample program below demonstrates these statistics.
Sample program file:
******** START OF FILE ******** #include <tracer.h> void foo() { TRACE_LIFETIME; usleep(rand() % 100000); } int main() { TRACE_LIFETIME; for(int i = 0; i < 100; ++i) foo(); } ******** END OF FILE ********
Produced log file:
******** START OF FILE ******** All the program time: 05265686 us (micro secs)
TRACE POINT: Function: int main() Calls: 0000000001 times Average T between calls: 0000000000 us Average life T: 0005264459 us File: main.cpp Line: 00000009
TRACE POINT: Function: void foo() Calls: 0000000100 times Average T between calls: 0000051665 us Average life T: 0000052606 us File: main.cpp Line: 00000004 ******** END OF FILE ********
Comment:
TRACE_LIFETIME is a MACRO that traces some scope statistics, namely: "Function" - the function name where the scope is; "Calls" - number of entries into this scope; "Average T between calls" - average time period between "Calls"; "Average life T" - average time spent in this scope.
Conclusion:
I think it is reasonable to introduce this trace functionality into (for example) boost::tracer namespace. I had wrote tracer.h and tracer.cpp source files and I wish Boost community to consider them.
Thank You. _______________________________________________ Unsubscribe & other changes: http://lists.boost.org/mailman/listinfo.cgi/boost
Hi, Boost.Chrono provide already this functionality with its new feature Stopwatch. See http://old.nabble.com/-chrono--v0.3--New-Stopwatch-Feature-tt27202338.html. Stopwatch is a an generic feature that allows the user to trace all you trace and more expect your "Average T between calls". stopclock<> provides a run time reporting package that can be invoked in a single line of code to report the usage of a Clock. stopclock_accumulator<> associates an accumulator with a stopwatch, so we are able to retrieve any statistical feature Boost.Accumulator provides. For example: . ******** START OF FILE ******** #include <boost/stopwatches.h> #include <cmath> #define TRACE_LIFETIME \ static boost::chrono::stopclock_accumulator<> acc(BOOST_CHRONO_ACCUMULATOR_FUNCTION_FORMAT); \ boost::chrono::stopclock_accumulator<>::scoped_run _(acc); int f1(long j) { TRACE_LIFETIME; for ( long i = 0; i < j; ++i ) std::sqrt( 123.456L ); // burn some time return 0; } int main() { TRACE_LIFETIME; f1(100000); f1(200000); f1(300000); return 0; } ******** END OF FILE ******** produce the output int f1(long int) : 3 times, sum=0.031s, min=0.006s, max=0.013s, mean=0.010s int main() : 1 times, sum=0.031s, min=0.031s, max=0.031s, mean=0.031s I'm interesteed in seen your code, could you upload it somewhere? Any comments on the Stopwatch part of the Chrono library is welcome. Best, Vicente ----- Original Message ----- From: "Andrew Chinkoff" <achinkoff@gmail.com> To: <boost@lists.boost.org> Sent: Wednesday, January 20, 2010 12:47 AM Subject: [boost] [Boost.tracer] library request
[Boost.tracer] library request is founded on a desire to trace some statistics about program execution.
The sample program below demonstrates these statistics.
Sample program file:
******** START OF FILE ******** #include <tracer.h> void foo() { TRACE_LIFETIME; usleep(rand() % 100000); } int main() { TRACE_LIFETIME; for(int i = 0; i < 100; ++i) foo(); } ******** END OF FILE ********
Produced log file:
******** START OF FILE ******** All the program time: 05265686 us (micro secs)
TRACE POINT: Function: int main() Calls: 0000000001 times Average T between calls: 0000000000 us Average life T: 0005264459 us File: main.cpp Line: 00000009
TRACE POINT: Function: void foo() Calls: 0000000100 times Average T between calls: 0000051665 us Average life T: 0000052606 us File: main.cpp Line: 00000004 ******** END OF FILE ********
Comment:
TRACE_LIFETIME is a MACRO that traces some scope statistics, namely: "Function" - the function name where the scope is; "Calls" - number of entries into this scope; "Average T between calls" - average time period between "Calls"; "Average life T" - average time spent in this scope.
Conclusion:
I think it is reasonable to introduce this trace functionality into (for example) boost::tracer namespace. I had wrote tracer.h and tracer.cpp source files and I wish Boost community to consider them.
Thank You. _______________________________________________ Unsubscribe & other changes: http://lists.boost.org/mailman/listinfo.cgi/boost
On 01/20/2010 02:47 AM, Andrew Chinkoff wrote:
[Boost.tracer] library request is founded on a desire to trace some statistics about program execution.
You might be interested in the Boost.Log library found here: http://tinyurl.com/cm9lum The docs are available online: http://tinyurl.com/5e4fd7 The library provides the way to set timers and monitor some activity on a time line. For example: void bar(); void foo() { logger lg; BOOST_LOG_SCOPED_THREAD_ATTR("Duration", timer); BOOST_LOG(lg) << "Start"; bar(); BOOST_LOG(lg) << "End"; } If formatting and sink are set up, it will produce something like this: [00:00:00.000000] Start [00:00:01.001793] End What's good is that if you write logs in bar(), they will be put on the time line between Start and End with the according time readings.
Andrew Chinkoff wrote:
[Boost.tracer] library request is founded on a desire to trace some statistics about program execution.
The sample program below demonstrates these statistics.
Sample program file:
******** START OF FILE ******** #include <tracer.h> void foo() { TRACE_LIFETIME; usleep(rand() % 100000); } int main() { TRACE_LIFETIME; for(int i = 0; i < 100; ++i) foo(); } ******** END OF FILE ********
Produced log file:
******** START OF FILE ******** All the program time: 05265686 us (micro secs)
TRACE POINT: Function: int main() Calls: 0000000001 times Average T between calls: 0000000000 us Average life T: 0005264459 us File: main.cpp Line: 00000009
TRACE POINT: Function: void foo() Calls: 0000000100 times Average T between calls: 0000051665 us Average life T: 0000052606 us File: main.cpp Line: 00000004 ******** END OF FILE ********
Comment:
TRACE_LIFETIME is a MACRO that traces some scope statistics, namely: "Function" - the function name where the scope is; "Calls" - number of entries into this scope; "Average T between calls" - average time period between "Calls"; "Average life T" - average time spent in this scope.
Conclusion:
I think it is reasonable to introduce this trace functionality into (for example) boost::tracer namespace. I had wrote tracer.h and tracer.cpp source files and I wish Boost community to consider them.
Thank You. _______________________________________________ Unsubscribe & other changes: http://lists.boost.org/mailman/listinfo.cgi/boost
I've used simpler implementations of things like this before and always had an issue with nested trace points (usually nested function calls where each function contains a trace point). When the nesting is deep enough, the cumulative overhead of all the tracing functionality made the data unreliable except for the inner-most trace points. It would be interesting to know which of Boost.Chrono, Boost.Tracer, and Boost.Log handle this the best.
I've used simpler implementations of things like this before and always had an issue with nested trace points (usually nested function calls where each function contains a trace point). When the nesting is deep enough, the cumulative overhead of all the tracing functionality made the data unreliable except for the inner-most trace points. It would be interesting to know which of Boost.Chrono, Boost.Tracer, and Boost.Log handle this the best.
As for Boost.Log, there's no difference in how many nested functions you call within the timed scope. Every log record (or trace point, as you would call it) simply acquires the actual timer value, and the complexity of this operation is constant.
----- Original Message ----- From: "Andrey Semashev" <andrey.semashev@gmail.com> To: <boost@lists.boost.org> Sent: Wednesday, January 20, 2010 7:15 PM Subject: Re: [boost] [Boost.tracer] library request
I've used simpler implementations of things like this before and always had an issue with nested trace points (usually nested function calls where each function contains a trace point). When the nesting is deep enough, the cumulative overhead of all the tracing functionality made the data unreliable except for the inner-most trace points. It would be interesting to know which of Boost.Chrono, Boost.Tracer, and Boost.Log handle this the best.
As for Boost.Log, there's no difference in how many nested functions you call within the timed scope. Every log record (or trace point, as you would call it) simply acquires the actual timer value, and the complexity of this operation is constant.
Hi, I think the questions was related to the time reported by the outer stopclocks. How reliable is this data? How many time is related to the specific code and how many to the fact we are logging in inner blocks? Are tour mechanism able to make the difference? Another issue is what time do we want to measure. Do we want to measure the time between elapsed between two time points start/stop or the time spent by the executed code between these time points? Note that we will need a thread specific Clock for the second case. Boost.Chrono provides two scoped classes that allows to suspend resume what in Boost.Chrono I call a stopwatch. This can be used to suspend the stopwatch counting. Here follows two use cases void f1() { static stopwatch<>::reporter t; // ... // call to some function we don't want to measure { stopwatch_suspender<stopwatch<>::reporter> _(t); external_function(); } } void f2() { static stopwatch<>::reporter t; // ... // do something we don't want to measure { stopwatch_suspender<stopwatch<>::reporter> _(t); // do something we don't want to measure { stopwatch_resumer<stopwatch<>::reporter> _(t); // do something we want to measure } } } Of course this do not respond to your requirement, but there is something we can learn from this examples. We can suspend the time. So we need to define a thread specific Clock that is able to be suspended. The stopwatch reporters can take advantage of this facility and in this case the first thing the reporters must do is to suspend the time of this suspendable and thread specific Clock. I think I can adapt the current implementation to take care of this kind of Clocks. I will implement such suspendable Clock, and see how different are the measures. What will be more difficult is to implement a thread specific clock as this depend on whether the platform provides it or not. Some platforms provide already this kind of Clocks, e.g. "If _POSIX_THREAD_CPUTIME is defined, implementations shall support clock ID values obtained by invoking pthread_getcpuclockid(), which represent the CPU-time clock of a given thread. Implementations shall also support the special clockid_t value CLOCK_THREAD_CPUTIME_ID, which represents the CPU-time clock of the calling thread when invoking one of the clock_*() or timer_*() functions. For these clock IDs, the values returned by clock_gettime() and specified by clock_settime() shall represent the amount of execution time of the thread associated with the clock. ". I don't know if Windows or other platforms provide such a clock type. Any hints would be appreciated. Even if we don't count some time while reporting we couldn't avoid to spend some time to make this counting possible. So the measure could not be completly reliable, but imo it could be acceptable compared to the time taken by the reporting. I hope that the time spent to avoid counting the reporting would not be bigger than the time to report ;-) Boost provides also a kind of stopwatches that are able to cumulate the samples and report only at the end of the program some statistical data, as min, max, mean ... This kind of watches are no subject to the time spent reporting, but cumulating the samples. Thanks for signaling this issue. Vicente
participants (4)
-
Andrew Chinkoff -
Andrey Semashev -
Kenny Riddile -
vicente.botet