timing question...

[Rick Riolo]

First let me note that I installed the fixes that Manor sent along
and they work fine...things link fine with the original SWARMLIBS line
in Makefile.conf, and the terminate trick works as well at stopping things.

However, I do have one mystery.

I have a little template 'model' object which is invoked from
a  main.m which has (in short, the full codes below):

simActions:  prestep, step, poststep
displayActions: stepReport 

Each of these prints a message to stdout 
(via fprintf(stdout,"text");fflush(stdout);).  
poststep also does the check for termination condition (stopT==T).
There is a finish method to close files, etc, before quiting.

To run the thing there is just:
   [swarmActivity run];
   fprintf(stdout,"=main, after [swarmActivity run] done.\n");fflush(stdout);
   [model finish];

Here is the output at the end of a short run:
--------------
...
>Model-prestep T=4 (stopT 5) ===========================
=Model-step 4.
=Model-poststep 4.
=Model-stepReport 4.
>Model-prestep T=5 (stopT 5) ===========================
=Model-step 5.
=Model-poststep 5.  ** Terminate msg sent  **
=main, after [swarmActivity run] done.
=Model-finish. T=5.

=Model-stepReport 5.
maria-rlr)
----------------

My question is:  Why does the last "=Model-stepReport" message get
printed *after* the "=Model-finish" message?
Is it just some output buffering/timing problem?
(I can't see why, since I fprintf and fflush, but I'm not unix/c guru.)
Does it mean that last stepReport method is actually get
executed after the finish method?
Why would that be?
(I also put a sleep(1) after the fprintf in each method,
but that didn't change the order.)

Am I missing something simple here?

Thanks for any advice.
 - r

Rick Riolo                       address@hidden
Program for Study of Complex Systems (PSCS)
1061 Randall Lab     University of Michigan
Ann Arbor MI 48109-1120
http://pscs.physics.lsa.umich.edu/rlr-home.html

============================
The codes from main.m:
---------------
...
        simActions = [ActionGroup create: mZone];  
        [simActions createActionTo: model message: M(prestep)];
        [simActions createActionTo: model message: M(step)];
        [simActions createActionTo: model message: M(poststep)];

        simSchedule = [Schedule createBegin: mZone];
        [simSchedule setRepeatInterval: 1];
        simSchedule = [simSchedule createEnd];
        [simSchedule at: 0 createActionTo: simActions message: M(perform)];

        // Create a group of display actions and a schedule for them. 
        displaySchedule = [Schedule createBegin: mZone];
        [displaySchedule setRepeatInterval: DisplayFrequency];
        displaySchedule = [displaySchedule createEnd];
        [displaySchedule at: 0 createActionTo: model message: M(stepReport)];

        // SwarmPlan to run the schedules
        swarmPlan = [SwarmPlan create: mZone];
        [swarmPlan createActionTo: simSchedule message: M(start)];
        [swarmPlan createActionTo: displaySchedule message: M(start)];

        // A swarmActivity whose job it is to execute the swarmPlan
        swarmActivity = [swarmPlan start];

        [swarmActivity run];
        fprintf(stdout,"=main, after [swarmActivity run] 
done.\n");fflush(stdout);
        sleep(1);
        [model finish];
        return 0;
}
------------
What the methods look like in Model.m:

-prestep {  // increment T, print a debug msg.
        unsigned int    u;
        extern id       uniformRandomR;

        ++T;
        fprintf(stdout,">Model-prestep T=%u (stopT %u) 
======================\n",
                  T, stopT );fflush(stdout);
        u = [uniformRandomR rMax: 7];
        DMsg2(1,"  RDebug %dL uniformRandomR(rMax=7)=> %u.\n",
                  RDebug, u );
        sleep(1);
        return self;
}
-step {
        fprintf(stdout,"=Model-step %d.\n", T );fflush(stdout);
        sleep(1);
        return self;
}
-poststep {
        fprintf(stdout,"=Model-poststep %d.", T );fflush(stdout);

        if ( T == stopT ) {     // generic stop condition
                [getTopLevelActivity() terminate];
                fprintf(stdout,"  ** Terminate msg sent  **");fflush(stdout);
        }
        if ( !stopOnlyAtT ) {
                // fill in specific stop condition, if needed
                // but only used if stopOnlyAtT is not turned on.
                ;
        }
        fprintf(stdout,"\n");fflush(stdout);
        sleep(1);
        return self;
}
-stepReport {
        fprintf(stdout,"=Model-stepReport %d.\n", T );fflush(stdout);
        sleep(1);

        fprintf(reportFILE,"  %3u\n", T );
        fflush(reportFILE);
        return self;
}
-finish {
        fprintf(stdout,"=Model-finish. T=%d.\n\n", T );fflush(stdout);
        sleep(1);

        // model specific processing here
        fprintf(reportFILE,"##########\n");
        fprintf(reportFILE,"#");  // write the last report data line on # line
        [self stepReport];
        fprintf(reportFILE,"##########\n");
        fprintf(reportFILE,"# Model run done at %s.\n", [self getTime] );


        // All models need this...
        if ( fclose( reportFILE ) ) {
                fprintf(stderr,"\n\nError closing reportFILE (%s).\n\n",
                                [self getStrParValueFor: "reportFileName"] );
        }
        return self;
}