diff --git a/Moose Development/Moose/Core/Base.lua b/Moose Development/Moose/Core/Base.lua index 5b766d10f..c042904a1 100644 --- a/Moose Development/Moose/Core/Base.lua +++ b/Moose Development/Moose/Core/Base.lua @@ -891,6 +891,26 @@ end -- Log a trace (only shown when trace is on) -- TODO: Make trace function using variable parameters. +--- Set trace on. +-- @param #BASE self +-- @usage +-- -- Switch the tracing On +-- BASE:TraceOn() +function BASE:TraceOn() + self:TraceOnOff( true ) +end + +--- Set trace off. +-- @param #BASE self +-- @usage +-- -- Switch the tracing Off +-- BASE:TraceOff() +function BASE:TraceOff() + self:TraceOnOff( false ) +end + + + --- Set trace on or off -- Note that when trace is off, no BASE.Debug statement is performed, increasing performance! -- When Moose is loaded statically, (as one file), tracing is switched off by default. @@ -905,7 +925,7 @@ end -- -- Switch the tracing Off -- BASE:TraceOnOff( false ) function BASE:TraceOnOff( TraceOnOff ) - _TraceOnOff = TraceOnOff + _TraceOnOff = TraceOnOff or true end @@ -925,8 +945,8 @@ end -- @param #BASE self -- @param #number Level function BASE:TraceLevel( Level ) - _TraceLevel = Level - self:I( "Tracing level " .. Level ) + _TraceLevel = Level or 1 + self:I( "Tracing level " .. _TraceLevel ) end --- Trace all methods in MOOSE @@ -934,7 +954,7 @@ end -- @param #boolean TraceAll true = trace all methods in MOOSE. function BASE:TraceAll( TraceAll ) - _TraceAll = TraceAll + _TraceAll = TraceAll or true if _TraceAll then self:I( "Tracing all methods in MOOSE " ) @@ -989,7 +1009,7 @@ function BASE:_F( Arguments, DebugInfoCurrentParam, DebugInfoFromParam ) if DebugInfoFrom then LineFrom = DebugInfoFrom.currentline end - env.info( string.format( "%6d(%6d)/%1s:%25s%05d.%s(%s)" , LineCurrent, LineFrom, "F", self.ClassName, self.ClassID, Function, routines.utils.oneLineSerialize( Arguments ) ) ) + env.info( string.format( "%6d(%6d)/%1s:%30s%05d.%s(%s)" , LineCurrent, LineFrom, "F", self.ClassName, self.ClassID, Function, routines.utils.oneLineSerialize( Arguments ) ) ) end end end @@ -1064,7 +1084,7 @@ function BASE:_T( Arguments, DebugInfoCurrentParam, DebugInfoFromParam ) if DebugInfoFrom then LineFrom = DebugInfoFrom.currentline end - env.info( string.format( "%6d(%6d)/%1s:%25s%05d.%s" , LineCurrent, LineFrom, "T", self.ClassName, self.ClassID, routines.utils.oneLineSerialize( Arguments ) ) ) + env.info( string.format( "%6d(%6d)/%1s:%30s%05d.%s" , LineCurrent, LineFrom, "T", self.ClassName, self.ClassID, routines.utils.oneLineSerialize( Arguments ) ) ) end end end @@ -1135,9 +1155,9 @@ function BASE:E( Arguments ) LineFrom = DebugInfoFrom.currentline end - env.info( string.format( "%6d(%6d)/%1s:%25s%05d.%s(%s)" , LineCurrent, LineFrom, "E", self.ClassName, self.ClassID, Function, routines.utils.oneLineSerialize( Arguments ) ) ) + env.info( string.format( "%6d(%6d)/%1s:%30s%05d.%s(%s)" , LineCurrent, LineFrom, "E", self.ClassName, self.ClassID, Function, routines.utils.oneLineSerialize( Arguments ) ) ) else - env.info( string.format( "%1s:%25s%05d(%s)" , "E", self.ClassName, self.ClassID, routines.utils.oneLineSerialize( Arguments ) ) ) + env.info( string.format( "%1s:%30s%05d(%s)" , "E", self.ClassName, self.ClassID, routines.utils.oneLineSerialize( Arguments ) ) ) end end @@ -1163,9 +1183,9 @@ function BASE:I( Arguments ) LineFrom = DebugInfoFrom.currentline end - env.info( string.format( "%6d(%6d)/%1s:%25s%05d.%s(%s)" , LineCurrent, LineFrom, "I", self.ClassName, self.ClassID, Function, routines.utils.oneLineSerialize( Arguments ) ) ) + env.info( string.format( "%6d(%6d)/%1s:%30s%05d.%s(%s)" , LineCurrent, LineFrom, "I", self.ClassName, self.ClassID, Function, routines.utils.oneLineSerialize( Arguments ) ) ) else - env.info( string.format( "%1s:%25s%05d(%s)" , "I", self.ClassName, self.ClassID, routines.utils.oneLineSerialize( Arguments ) ) ) + env.info( string.format( "%1s:%30s%05d(%s)" , "I", self.ClassName, self.ClassID, routines.utils.oneLineSerialize( Arguments ) ) ) end end diff --git a/Moose Development/Moose/Core/Fsm.lua b/Moose Development/Moose/Core/Fsm.lua index 22489bc7c..5149b4aa6 100644 --- a/Moose Development/Moose/Core/Fsm.lua +++ b/Moose Development/Moose/Core/Fsm.lua @@ -594,7 +594,17 @@ do -- FSM return errmsg end if self[handler] then - self:T( "*** FSM *** " .. step .. " *** " .. params[1] .. " --> " .. params[2] .. " --> " .. params[3] ) + if step == "onafter" or step == "OnAfter" then + self:T( ":::>" .. step .. params[2] .. " : " .. params[1] .. " >> " .. params[2] .. ">" .. step .. params[2] .. "()" .. " >> " .. params[3] ) + elseif step == "onbefore" or step == "OnBefore" then + self:T( ":::>" .. step .. params[2] .. " : " .. params[1] .. " >> " .. step .. params[2] .. "()" .. ">" .. params[2] .. " >> " .. params[3] ) + elseif step == "onenter" or step == "OnEnter" then + self:T( ":::>" .. step .. params[3] .. " : " .. params[1] .. " >> " .. params[2] .. " >> " .. step .. params[3] .. "()" .. ">" .. params[3] ) + elseif step == "onleave" or step == "OnLeave" then + self:T( ":::>" .. step .. params[1] .. " : " .. params[1] .. ">" .. step .. params[1] .. "()" .. " >> " .. params[2] .. " >> " .. params[3] ) + else + self:T( ":::>" .. step .. " : " .. params[1] .. " >> " .. params[2] .. " >> " .. params[3] ) + end self._EventSchedules[EventName] = nil local Result, Value = xpcall( function() return self[handler]( self, unpack( params ) ) end, ErrorHandler ) return Value @@ -718,13 +728,13 @@ do -- FSM if DelaySeconds < 0 then -- Only call the event ONCE! DelaySeconds = math.abs( DelaySeconds ) if not self._EventSchedules[EventName] then - CallID = self.CallScheduler:Schedule( self, self._handler, { EventName, ... }, DelaySeconds or 1, nil, nil, nil, 4 ) + CallID = self.CallScheduler:Schedule( self, self._handler, { EventName, ... }, DelaySeconds or 1, nil, nil, nil, 4, true ) self._EventSchedules[EventName] = CallID else -- reschedule end else - CallID = self.CallScheduler:Schedule( self, self._handler, { EventName, ... }, DelaySeconds or 1, nil, nil, nil, 4 ) + CallID = self.CallScheduler:Schedule( self, self._handler, { EventName, ... }, DelaySeconds or 1, nil, nil, nil, 4, true ) end else error( "FSM: An asynchronous event trigger requires a DelaySeconds parameter!!! This can be positive or negative! Sorry, but will not process this." ) diff --git a/Moose Development/Moose/Core/ScheduleDispatcher.lua b/Moose Development/Moose/Core/ScheduleDispatcher.lua index 0a70ca72d..ec03bc93b 100644 --- a/Moose Development/Moose/Core/ScheduleDispatcher.lua +++ b/Moose Development/Moose/Core/ScheduleDispatcher.lua @@ -52,7 +52,7 @@ end -- Nothing of this code should be modified without testing it thoroughly. -- @param #SCHEDULEDISPATCHER self -- @param Core.Scheduler#SCHEDULER Scheduler -function SCHEDULEDISPATCHER:AddSchedule( Scheduler, ScheduleFunction, ScheduleArguments, Start, Repeat, Randomize, Stop, TraceLevel ) +function SCHEDULEDISPATCHER:AddSchedule( Scheduler, ScheduleFunction, ScheduleArguments, Start, Repeat, Randomize, Stop, TraceLevel, Fsm ) self:F2( { Scheduler, ScheduleFunction, ScheduleArguments, Start, Repeat, Randomize, Stop, TraceLevel } ) self.CallID = self.CallID + 1 @@ -85,13 +85,40 @@ function SCHEDULEDISPATCHER:AddSchedule( Scheduler, ScheduleFunction, ScheduleAr self.Schedule[Scheduler][CallID].Randomize = Randomize or 0 self.Schedule[Scheduler][CallID].Stop = Stop - local Source = "" - local Line = "" + + -- This section handles the tracing of the scheduled calls. + -- Because these calls will be executed with a delay, we inspect the place where these scheduled calls are initiated. + -- The Info structure contains the output of the debug.getinfo() calls, which inspects the call stack for the function name, line number and source name. + -- The call stack has many levels, and the correct semantical function call depends on where in the code AddSchedule was "used". + -- - Using SCHEDULER:New() + -- - Using Schedule:AddSchedule() + -- - Using Fsm:__Func() + -- - Using Class:ScheduleOnce() + -- - Using Class:ScheduleRepeat() + -- - ... + -- So for each of these scheduled call variations, AddSchedule is the workhorse which will schedule the call. + -- But the correct level with the correct semantical function location will differ depending on the above scheduled call invocation forms. + -- That's where the field TraceLevel contains optionally the level in the call stack where the call information is obtained. + -- The TraceLevel field indicates the correct level where the semantical scheduled call was invoked within the source, ensuring that function name, line number and source name are correct. + -- There is one quick ... + -- The FSM class models scheduled calls using the __Func syntax. However, these functions are "tailed". + -- There aren't defined anywhere within the source code, but rather implemented as triggers within the FSM logic, + -- and using the onbefore, onafter, onenter, onleave prefixes. (See the FSM for details). + -- Therefore, in the call stack, at the TraceLevel these functions are mentioned as "tail calls", and the Info.name field will be nil as a result. + -- To obtain the correct function name for FSM object calls, the function is mentioned in the call stack at a higher stack level. + -- So when function name stored in Info.name is nil, then I inspect the function name within the call stack one level higher. + -- So this little piece of code does its magic wonderfully, preformance overhead is neglectible, as scheduled calls don't happen that often. + + local Info = {} if debug then TraceLevel = TraceLevel or 2 - Source = debug.getinfo( TraceLevel, "S" ).source - Line = debug.getinfo( TraceLevel, "nl" ).currentline + Info = debug.getinfo( TraceLevel, "nlS" ) + local name_fsm = debug.getinfo( TraceLevel - 1, "n" ).name -- #string + if name_fsm then + Info.name = name_fsm + end + --env.info( debug.traceback() ) end self:T3( self.Schedule[Scheduler][CallID] ) @@ -99,8 +126,10 @@ function SCHEDULEDISPATCHER:AddSchedule( Scheduler, ScheduleFunction, ScheduleAr self.Schedule[Scheduler][CallID].CallHandler = function( Params ) local CallID = Params.CallID - local Source = Params.Source - local Line = Params.Line + local Info = Params.Info + local Source = Info.source + local Line = Info.currentline + local Name = Info.name or "?" local ErrorHandler = function( errmsg ) env.info( "Error in timer function: " .. errmsg ) @@ -134,19 +163,19 @@ function SCHEDULEDISPATCHER:AddSchedule( Scheduler, ScheduleFunction, ScheduleAr local Stop = Schedule.Stop or 0 local ScheduleID = Schedule.ScheduleID - local Prefix = ( Repeat == 0 ) and " ---> " or " +++> " + local Prefix = ( Repeat == 0 ) and "--->" or "+++>" local Status, Result --self:E( { SchedulerObject = SchedulerObject } ) if SchedulerObject then local function Timer() - SchedulerObject:T( Prefix .. ( Source or "-" ) .. ": " .. ( Line or "-" ) ) + SchedulerObject:T( Prefix .. Name .. ":" .. Line .. " (" .. Source .. ")" ) return ScheduleFunction( SchedulerObject, unpack( ScheduleArguments ) ) end Status, Result = xpcall( Timer, ErrorHandler ) else local function Timer() - self:T( Prefix .. ( Source or "-" ) .. ": " .. ( Line or "-" ) ) + self:T( Prefix .. Name .. ":" .. Line .. " (" .. Source .. ")" ) return ScheduleFunction( unpack( ScheduleArguments ) ) end Status, Result = xpcall( Timer, ErrorHandler ) @@ -177,13 +206,13 @@ function SCHEDULEDISPATCHER:AddSchedule( Scheduler, ScheduleFunction, ScheduleAr self:Stop( Scheduler, CallID ) end else - self:I( " <<<> " .. ( Source or "-" ) .. ": " .. ( Line or "-" ) ) + self:I( "<<<>" .. Name .. ":" .. Line .. " (" .. Source .. ")" ) end return nil end - self:Start( Scheduler, CallID, Source, Line ) + self:Start( Scheduler, CallID, Info ) return CallID end @@ -197,7 +226,7 @@ function SCHEDULEDISPATCHER:RemoveSchedule( Scheduler, CallID ) end end -function SCHEDULEDISPATCHER:Start( Scheduler, CallID, Source, Line ) +function SCHEDULEDISPATCHER:Start( Scheduler, CallID, Info ) self:F2( { Start = CallID, Scheduler = Scheduler } ) if CallID then @@ -208,13 +237,13 @@ function SCHEDULEDISPATCHER:Start( Scheduler, CallID, Source, Line ) Schedule[CallID].StartTime = timer.getTime() -- Set the StartTime field to indicate when the scheduler started. Schedule[CallID].ScheduleID = timer.scheduleFunction( Schedule[CallID].CallHandler, - { CallID = CallID, Source = Source, Line = Line }, + { CallID = CallID, Info = Info }, timer.getTime() + Schedule[CallID].Start ) end else for CallID, Schedule in pairs( self.Schedule[Scheduler] or {} ) do - self:Start( Scheduler, CallID, Source, Line ) -- Recursive + self:Start( Scheduler, CallID, Info ) -- Recursive end end end diff --git a/Moose Development/Moose/Core/Scheduler.lua b/Moose Development/Moose/Core/Scheduler.lua index 198329c88..df54ced90 100644 --- a/Moose Development/Moose/Core/Scheduler.lua +++ b/Moose Development/Moose/Core/Scheduler.lua @@ -238,7 +238,7 @@ end -- @param #number RandomizeFactor Specifies a randomization factor between 0 and 1 to randomize the Repeat. -- @param #number Stop Specifies the amount of seconds when the scheduler will be stopped. -- @return #number The ScheduleID of the planned schedule. -function SCHEDULER:Schedule( SchedulerObject, SchedulerFunction, SchedulerArguments, Start, Repeat, RandomizeFactor, Stop, TraceLevel ) +function SCHEDULER:Schedule( SchedulerObject, SchedulerFunction, SchedulerArguments, Start, Repeat, RandomizeFactor, Stop, TraceLevel, Fsm ) self:F2( { Start, Repeat, RandomizeFactor, Stop } ) self:T3( { SchedulerArguments } ) @@ -257,7 +257,8 @@ function SCHEDULER:Schedule( SchedulerObject, SchedulerFunction, SchedulerArgume Repeat, RandomizeFactor, Stop, - TraceLevel or 3 + TraceLevel or 3, + Fsm ) self.Schedules[#self.Schedules+1] = ScheduleID