RE: [boost] high_resolution_timer \ timer featurerequests forBoost.Timerr

From: Brian Braatz (brianb_at_[hidden])
Date: 2005-03-05 02:12:43

> -----Original Message-----
> On Behalf Of James Fowler
> Sent: Friday, March 04, 2005 1:10 PM
> Brian Braatz wrote:
> 
> >First off- note that Timer can take a start time on the ctor: ...
> >
> >high_resolution_timer does not however: ...
> >
> >    high_resolution_timer() { ...
> >        if (!QueryPerformanceFrequency(&frequency))
> >            throw std::runtime_error("Couldn't acquire frequency");
> >...
> >
> >MY PROBLEM:
> >      I need to feed the timer the START time (or get FROM it the
start
> >time would be preferred)
> >
> >The reason I need this is because for logging purposes (working with
the
> >Profiler from Christopher Diggins) I need to log the start and stop
> >times, and I need it to (for internal cross reference) be the same
> >number for multiple purposes.
> >

[Brian Braatz Writes:] 
My most basic problem is high_resolution_timer and boost.timer have
different interfaces, one takes a time to start with the other does not.
I realize the high_resolution_timer is windows only and I realize that
the struct it uses to store the time is windows specific. 

At the simplest level I am asking for this:
Have both high_resolution_timer and timer support:

* Typedef's for the internal TYPE

* Same construction interface using that type

* Accessor method to GET to the internal data

Then I could accomplish what I am trying to do- I am not just measuring
things, but putting a layer on top. I can live with the issues with
timers. What I am after is being able to do this-
        Record profile LOGS in different threads (not reports, but logs
of every call that happened), spit out the approximate TIME each one of
those events occurred, this gives the human reader a conceptual way to
connect the different logs in time-
        Right now I am using hours, mins, seconds for this, getting to
the internal time is one way , the other is to make a redundant call to
QueryPerformanceCounter() or what have you.

This probably gets into the deeper question of "are these classes
supposed to have roles that extend a bit beyond just holding time
duration?"

If nothing else, I ask that making the interface amongst the timers be
the same (same ctor style and the typedef so I can write code against
either)

> >
> IMHO, based on the example you gave, you're mixing two separate
> problems:  how to capture a representation of current time, and how to
> present an interface to capture durations of time.  I haven't really
> examined the Profiler mentioned lately in detail, so maybe you've
> actually already dealt with this in the real code.  If so, I'd like to
> take a look, as I'm working through similar issues myself.  If not,
I'm
> working on something that be useful to you.

[Brian Braatz Writes:] 

Yes, I am mixing many problems. I am building something on top of
Profiler (by Chris Diggings) to also do log tracing, and do it
multi-threaded- So now I can see the normal profile report, AND I can
also turn on DEEP TRACING which will tell me all the calls that occurred
and how long they took.

(the sample below doesn't show it, but I have need of getting the
internal time data and using it to get a sense of "roughly" when 2
threads of execution are near-about each other- it can be a little off
and that is fine)

Here is some samples of what I have working:
(EVENT_BEGIN and EVEN_END define the profiler objects which use RAII to
engage and disengage the profile point)

    (sample code to test the profiler \ logger)

    class Fname
    {
        public:
            void SetText()
            {
                EVENT_BEGIN(Fname,SetText);
                    Sleep(300);
                EVENT_END(Fname,SetText);
          }
    
    };
    
    class EntryScreen
    {
        Fname m_FName;
        
        public:
            void DoSomethingElse()
            {
                EVENT_BEGIN(EntryScreen,DoSomethingElse);
                    PROFILE_CHECKPOINT(DataBaseOperation);
                    Sleep(1234);
                EVENT_END(EntryScreen,DoSomethingElse);
            }
             void DoOtherStuff()
            {
                EVENT_BEGIN(EntryScreen,DoOtherStuff);
                    Sleep(1432);
                    m_FName.SetText();
                EVENT_END(EntryScreen,DoOtherStuff);
            }
   
    };

    class MainWindow
    {
        EntryScreen r;
        public:
            void DoSomething()
            {
                EVENT_BEGIN(MainWindow,DoSomething);
                {   
                    r.DoSomethingElse();    
                    r.DoOtherStuff();        
                }
                EVENT_END(MainWindow,DoSomething);
            
            }                            
    
    };

Test()
{
        MainWindow in;
        In.DoSomething();
}
        
Here is the profile REPORT:
(this is what the Profiler that Mr Diggins started produces)

profile 	total   	count   	mean    	percent 
CP-DataBaseOperation	1.230334	1	1.230334
16.392611
Fname#SetText		0.312570	1	0.312570	4.164595
MainWindow#DoSomething	2.981596	1	2.981596
39.725903
EntryScreen#DoOtherStuff	1.750382	1	1.750382
23.321574
EntryScreen#DoSomethingElse	1.230537	1	1.230537
16.395316
total entries	5
total time elapsed	7.505420
overall average	1.501084

NOW- here is the LOG 
DEPTH	DATE		TIME		NAME
ELAPSED
1	3/4/2005	17:06:02	MainWindow#DoSomething	2.98135
2	3/4/2005	17:06:02	EntryScreen#DoSomethingElse
1.23054
2	3/4/2005	17:06:03	EntryScreen#DoOtherStuff
1.75038
3	3/4/2005	17:06:05	Fname#SetText		0.312562

NOTE THE DEPTH COL- by reading this I can tell that:

MainWindow#DoSomething ran for about 3 seconds total
        it called doSomethingElse- which ran for 1.2 seconds
        then DoSomething called DoOtherStuff() which then called SetText

(the depth col makes it a tree)

LONG TERM GOALS FOR ME:

1- Get this finished in my production app and working to solve some real
problems
2- Merge the logging stuff with the profiler library
3- finish the process of getting this ready for boost

EXTREMELY LONG TERM GOALS for the profiling library:
* Use wave to parse the boost source code- and make a copy of all the
code and insert the profling code INTO the boost libraries
        Then run the unit tests on the mangled code- spitting out
performance info
* integrate this with unit testing so that boost libraries can now be
tested with integrated profiling
        Would like to see how the different libraries perform on
different platforms with different compilers
        Would like boost to have yet something else the other libraries
of the world do not (I love boost and want to help move it along in any
way I can figure out)

> 
> Here's some food for thought:
> 
>     * interface issues for capturing durations
>           o consistent, portable representation
>           o normalized conversion(s) for use in external expressions
>             (i.e., as double representing seconds)
>           o support for internal expressions (add, subtract, compare)
>           o variety of use cases for establishing boundary moments

[Brian Braatz Writes:] 
(snip)
        I have read this mail several times and have saved it for
reference, I am not a timer expert and VERY MUCH appreciate the
information THANK YOU.
(and yes it sounds like this work would make what I am working on
better)

> 
> Hopefully this gives a taste of the complexities surrounding the
> seemingly simple task of getting a precise representation of "now".
It
> can be a very dangerous area to explore for anyone with
perfectionistic
> tendencies ;) .  IMHO this is a classic "can't see the forest for the

[Brian Braatz Writes:] 
Yes, I will be running into more of these as I move forward, I am in the
basic stages right now.
Fundamentally, I have an app that has some weird performance issues, and
I am working on "baking in" logging and performance analysis to help
debug these production issues. So my needs are *very much* from the
front lines :) 

> trees" issue (and I've gotten lost in that forest a few times over the
> years...).  With the myriad possibilities for differing results driven
> by the matrix of potential variation,  trying to predict just how a
> given combination will behave becomes an exasperating challenge.  How
> can we get past that?  Stop trying to predict the results.  Go produce
> the results instead.  Line up all the possible combinations that can
> work on a given platform, turn them loose and take notes.  Pinning
exact
> timing on individual moments may always involve a little uncertainty,
> but analyzing average trends can lead to deeper insights and
justifiable
> confidence in the system overall.   Some of the issues with
> QueryPerformanceCounter(...) may certainly be "real",  yet their
impact
> on the real world of your applications may prove irrelevant with a
> little testing.
> 

[Brian Braatz Writes:] 

I agree :) For the most part- I am LOOKING for things like this-
(example) today the application took 30 seconds to perform an operation
that should take 10 seconds. So the issues with realtime ARE important
for me from a boost sense, but are livable for the production problem I
am working on.

> >
> >MY REQUESTS:...
> >
> >There you go, those are my requests. Now I will sit here quietly and
> >hope there is a Santa Claus....
> >
> >(grin)
> >
> >
> So was this less, or more, than you asked for?  Although I suppose
you'd
> rather have it done than have it described. :)  Alas, for that you'll
> have to be patient, but perhaps not for long.  Since I'm in the
process
> of writing documentation which needed to address high resolution
timing
> anyway,  organizing my thoughts in this response probably helped me
more
> than it will help you!  At least, until the whole package is ready to
go
> under the tree...
> 
> - james

[Brian Braatz Writes:] 
It was WAY more than I asked for, and thank you for the brain dump and
stimulating discussion. :)