Index: generic/gentclAPI.tcl =================================================================== diff -u -r62beaf105e751bb647d88153700253b4c6723127 -rc5f2227387dec2a5c0af9b36dc1ebc8578d6603e --- generic/gentclAPI.tcl (.../gentclAPI.tcl) (revision 62beaf105e751bb647d88153700253b4c6723127) +++ generic/gentclAPI.tcl (.../gentclAPI.tcl) (revision c5f2227387dec2a5c0af9b36dc1ebc8578d6603e) @@ -194,6 +194,7 @@ "tclobj" {set type "Tcl_Obj *"} "int" {set type "Tcl_Obj *"} "int32" {set type "int "} + "boolean" {set type "int "} "*|*" {set type "int "} default {error "type '$(-type)' not allowed for parameter"} } Index: generic/nsf.c =================================================================== diff -u -r453ad27418d60f0ab744ae4ac911bcd5e2505140 -rc5f2227387dec2a5c0af9b36dc1ebc8578d6603e --- generic/nsf.c (.../nsf.c) (revision 453ad27418d60f0ab744ae4ac911bcd5e2505140) +++ generic/nsf.c (.../nsf.c) (revision c5f2227387dec2a5c0af9b36dc1ebc8578d6603e) @@ -12544,9 +12544,9 @@ */ /*fprintf(stderr, ".... ensemble dispatch object %s self %s pass %s\n", - ObjectName(object), ObjectName(self), (self->flags & NSF_KEEP_CALLER_SELF) ? "callerSelf" : "invokedObject"); + ObjectName(invokedObject), ObjectName(actualSelf), (actualSelf->flags & NSF_KEEP_CALLER_SELF) ? "callerSelf" : "invokedObject"); fprintf(stderr, ".... ensemble dispatch on %s.%s objflags %.8x cscPtr %p base flags %.6x flags %.6x cl %s\n", - ObjectName(actualSelf), subMethodName, self->flags, + ObjectName(actualSelf), subMethodName, actualSelf->flags, cscPtr, (0xFF & cscPtr->flags), (cscPtr->flags & 0xFF)|NSF_CSC_IMMEDIATE, (actualClass != NULL) ? ClassName(actualClass) : "NONE");*/ result = MethodDispatch(actualSelf, interp, objc-1, objv+1, @@ -13198,8 +13198,6 @@ methodObj, methodObj->refCount, methodName, methodObj->typePtr, (methodObj->typePtr != NULL) ? methodObj->typePtr->name : ""); #endif - NSF_PROFILE_CALL(interp, object, ObjStr(methodObj)); - /*fprintf(stderr, "ObjectDispatch obj = %s objc = %d 0=%s methodName=%s shift %d\n", (object != NULL) ? ObjectName(object) : NULL, objc, objv[0] ? ObjStr(objv[0]) : NULL, methodName, shift);*/ @@ -13709,6 +13707,7 @@ object->flags |= NSF_DESTROY_CALLED; if (CallDirectly(interp, object, NSF_o_destroy_idx, &methodObj)) { + NSF_PROFILE_TIME_DATA; NSF_PROFILE_CALL(interp, object, Nsf_SystemMethodOpts[NSF_o_destroy_idx]); result = NsfODestroyMethod(interp, object); NSF_PROFILE_EXIT(interp, object, Nsf_SystemMethodOpts[NSF_o_destroy_idx]); @@ -16186,12 +16185,6 @@ CheckCStack(interp, "nsfProc", fullMethodName); -#if defined(NSF_PROFILE) - if (rst->doTrace) { - NsfProfileTraceCallAppend(interp, fullMethodName); - } -#endif - /* * The code below is derived from the scripted method dispatch and just * slightly adapted to remove object dependencies. @@ -16227,6 +16220,12 @@ #endif } +#if defined(NSF_PROFILE) + if (rst->doTrace) { + NsfProfileTraceCallAppend(interp, fullMethodName); + } +#endif + procPtr = (Proc *)Tcl_Command_objClientData(cmd); result = TclPushStackFrame(interp, &framePtr, (Tcl_Namespace *) procPtr->cmdPtr->nsPtr, @@ -19262,14 +19261,15 @@ * Call configure method */ if (CallDirectly(interp, object, NSF_o_configure_idx, &methodObj)) { + NSF_PROFILE_TIME_DATA; if (methodObj == NULL) { methodObj = NsfGlobalObjs[NSF_CONFIGURE]; } assert(methodObj != NULL); /* methodObj is just for error reporting */ NSF_PROFILE_CALL(interp, object, ObjStr(methodObj)); result = NsfOConfigureMethod(interp, object, objc, objv, methodObj); - //NSF_PROFILE_EXIT(interp, object, ObjStr(methodObj)); + NSF_PROFILE_EXIT(interp, object, ObjStr(methodObj)); } else { result = CallMethod(object, interp, methodObj, objc+2, objv, NSF_CSC_IMMEDIATE); } @@ -23887,6 +23887,25 @@ } /* +cmd __profile_trace NsfProfileTraceStub { + {-argName "-enable" -required 1 -nrargs 1 -type boolean} + {-argName "-verbose" -required 0 -nrargs 1 -type boolean} +} +*/ +static int NsfProfileTraceStub(Tcl_Interp *interp, int withEnable, int withVerbose) + NSF_nonnull(1); + +static int +NsfProfileTraceStub(Tcl_Interp *interp, int withEnable, int withVerbose) { + assert(interp != NULL); + +#if defined(NSF_PROFILE) + NsfProfileTrace(interp, withEnable, withVerbose); +#endif + return TCL_OK; +} + +/* *---------------------------------------------------------------------- * NsfUnsetUnknownArgsCmd -- * @@ -24123,11 +24142,9 @@ #if defined(NSF_PROFILE) RUNTIME_STATE(interp)->doTrace = bool; /* - * Turn on autormically profiling, when trace is turned on. + * Turn automically profiling on&off, when trace is turned on/off */ - if (bool) { - RUNTIME_STATE(interp)->doProfile = bool; - } + RUNTIME_STATE(interp)->doProfile = bool; #else NsfLog(interp, NSF_LOG_WARN, "No profile support compiled in"); #endif @@ -27847,6 +27864,7 @@ ((Command *)object->id)->flags == 0 ? ObjectName(object) : "(deleted)");*/ if (CallDirectly(interp, &object->cl->object, NSF_c_dealloc_idx, &methodObj)) { + NSF_PROFILE_TIME_DATA; NSF_PROFILE_CALL(interp, &object->cl->object, Nsf_SystemMethodOpts[NSF_c_dealloc_idx]); result = DoDealloc(interp, object); NSF_PROFILE_EXIT(interp, &object->cl->object, Nsf_SystemMethodOpts[NSF_c_dealloc_idx]); @@ -28507,6 +28525,7 @@ /* call recreate --> initialization */ if (CallDirectly(interp, &cl->object, NSF_c_recreate_idx, &methodObj)) { + NSF_PROFILE_TIME_DATA; NSF_PROFILE_CALL(interp, &cl->object, Nsf_SystemMethodOpts[NSF_c_recreate_idx]); result = RecreateObject(interp, cl, newObject, objc, objv); NSF_PROFILE_EXIT(interp, &cl->object, Nsf_SystemMethodOpts[NSF_c_recreate_idx]); @@ -28540,6 +28559,7 @@ */ if (CallDirectly(interp, &cl->object, NSF_c_alloc_idx, &methodObj)) { + NSF_PROFILE_TIME_DATA; NSF_PROFILE_CALL(interp, &cl->object, Nsf_SystemMethodOpts[NSF_c_alloc_idx]); result = NsfCAllocMethod_(interp, cl, nameObj, parentNsPtr); NSF_PROFILE_EXIT(interp, &cl->object, Nsf_SystemMethodOpts[NSF_c_alloc_idx]); @@ -28768,6 +28788,7 @@ callDirectly = CallDirectly(interp, &cl->object, NSF_c_create_idx, &methodObj); if (callDirectly != 0) { + NSF_PROFILE_TIME_DATA; NSF_PROFILE_CALL(interp, &cl->object, Nsf_SystemMethodOpts[NSF_c_create_idx]); result = NsfCCreateMethod(interp, cl, fullnameObj, objc, objv); NSF_PROFILE_EXIT(interp, &cl->object, Nsf_SystemMethodOpts[NSF_c_create_idx]); @@ -28830,6 +28851,7 @@ * Dispatch "cleanup" method. */ if (CallDirectly(interp, object, NSF_o_cleanup_idx, &methodObj)) { + NSF_PROFILE_TIME_DATA; /*fprintf(stderr, "RECREATE calls cleanup directly for object %s\n", ObjectName(object));*/ NSF_PROFILE_CALL(interp, object, Nsf_SystemMethodOpts[NSF_o_cleanup_idx]); result = NsfOCleanupMethod(interp, object); Index: generic/nsf.h =================================================================== diff -u -r6b00c4eaf55fa4d9c37dc86e3323003610548732 -rc5f2227387dec2a5c0af9b36dc1ebc8578d6603e --- generic/nsf.h (.../nsf.h) (revision 6b00c4eaf55fa4d9c37dc86e3323003610548732) +++ generic/nsf.h (.../nsf.h) (revision c5f2227387dec2a5c0af9b36dc1ebc8578d6603e) @@ -221,7 +221,8 @@ #if defined(NSF_PROFILE) || defined(NSF_DTRACE) # define CscInit(cscPtr, object, cl, cmd, frametype, flags, method) \ - CscInit_(cscPtr, object, cl, cmd, frametype, flags); cscPtr->methodName = (method); + CscInit_(cscPtr, object, cl, cmd, frametype, flags); cscPtr->methodName = (method); \ + NsfProfileTraceCall(interp, (object), cscPtr->methodName); #else # define CscInit(cscPtr, object, cl, cmd, frametype, flags, methodName) \ CscInit_(cscPtr, object, cl, cmd, frametype, flags) Index: generic/nsfAPI.decls =================================================================== diff -u -re1c25b411ed784b0f32610f04d2d7188f9cca418 -rc5f2227387dec2a5c0af9b36dc1ebc8578d6603e --- generic/nsfAPI.decls (.../nsfAPI.decls) (revision e1c25b411ed784b0f32610f04d2d7188f9cca418) +++ generic/nsfAPI.decls (.../nsfAPI.decls) (revision c5f2227387dec2a5c0af9b36dc1ebc8578d6603e) @@ -56,6 +56,12 @@ } cmd __profile_clear NsfProfileClearDataStub {} cmd __profile_get NsfProfileGetDataStub {} +cmd __profile_get NsfProfileGetDataStub {} +cmd __profile_trace NsfProfileTraceStub { + {-argName "-enable" -required 1 -nrargs 1 -type boolean} + {-argName "-verbose" -required 0 -nrargs 1 -type boolean} +} + cmd __unset_unknown_args NsfUnsetUnknownArgsCmd {} cmd "asm::proc" NsfAsmProcCmd { Index: generic/nsfAPI.h =================================================================== diff -u -re1c25b411ed784b0f32610f04d2d7188f9cca418 -rc5f2227387dec2a5c0af9b36dc1ebc8578d6603e --- generic/nsfAPI.h (.../nsfAPI.h) (revision e1c25b411ed784b0f32610f04d2d7188f9cca418) +++ generic/nsfAPI.h (.../nsfAPI.h) (revision c5f2227387dec2a5c0af9b36dc1ebc8578d6603e) @@ -281,7 +281,7 @@ /* just to define the symbol */ -static Nsf_methodDefinition method_definitions[110]; +static Nsf_methodDefinition method_definitions[111]; static const char *method_command_namespace_names[] = { "::nsf::methods::object::info", @@ -407,6 +407,8 @@ NSF_nonnull(2) NSF_nonnull(4); static int NsfProfileGetDataStubStub(ClientData clientData, Tcl_Interp *interp, int objc, Tcl_Obj *CONST* objv) NSF_nonnull(2) NSF_nonnull(4); +static int NsfProfileTraceStubStub(ClientData clientData, Tcl_Interp *interp, int objc, Tcl_Obj *CONST* objv) + NSF_nonnull(2) NSF_nonnull(4); static int NsfRelationGetCmdStub(ClientData clientData, Tcl_Interp *interp, int objc, Tcl_Obj *CONST* objv) NSF_nonnull(2) NSF_nonnull(4); static int NsfRelationSetCmdStub(ClientData clientData, Tcl_Interp *interp, int objc, Tcl_Obj *CONST* objv) @@ -626,6 +628,8 @@ NSF_nonnull(1); static int NsfProfileGetDataStub(Tcl_Interp *interp) NSF_nonnull(1); +static int NsfProfileTraceStub(Tcl_Interp *interp, int withEnable, int withVerbose) + NSF_nonnull(1); static int NsfRelationGetCmd(Tcl_Interp *interp, NsfObject *object, int type) NSF_nonnull(1) NSF_nonnull(2); static int NsfRelationSetCmd(Tcl_Interp *interp, NsfObject *object, int type, Tcl_Obj *value) @@ -787,6 +791,7 @@ NsfProcCmdIdx, NsfProfileClearDataStubIdx, NsfProfileGetDataStubIdx, + NsfProfileTraceStubIdx, NsfRelationGetCmdIdx, NsfRelationSetCmdIdx, NsfSelfCmdIdx, @@ -2198,6 +2203,27 @@ } static int +NsfProfileTraceStubStub(ClientData clientData, Tcl_Interp *interp, int objc, Tcl_Obj *CONST* objv) { + ParseContext pc; + (void)clientData; + + if (likely(ArgumentParse(interp, objc, objv, NULL, objv[0], + method_definitions[NsfProfileTraceStubIdx].paramDefs, + method_definitions[NsfProfileTraceStubIdx].nrParameters, 0, NSF_ARGPARSE_BUILTIN, + &pc) == TCL_OK)) { + int withEnable = (int )PTR2INT(pc.clientData[0]); + int withVerbose = (int )PTR2INT(pc.clientData[1]); + + assert(pc.status == 0); + return NsfProfileTraceStub(interp, withEnable, withVerbose); + + } else { + + return TCL_ERROR; + } +} + +static int NsfRelationGetCmdStub(ClientData clientData, Tcl_Interp *interp, int objc, Tcl_Obj *CONST* objv) { ParseContext pc; (void)clientData; @@ -3292,7 +3318,7 @@ } } -static Nsf_methodDefinition method_definitions[110] = { +static Nsf_methodDefinition method_definitions[111] = { {"::nsf::methods::class::alloc", NsfCAllocMethodStub, 1, { {"objectName", NSF_ARG_REQUIRED, 1, Nsf_ConvertTo_Tclobj, NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL}} }, @@ -3575,6 +3601,10 @@ {"::nsf::__profile_get", NsfProfileGetDataStubStub, 0, { {NULL, 0, 0, NULL, NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL}} }, +{"::nsf::__profile_trace", NsfProfileTraceStubStub, 2, { + {"-enable", NSF_ARG_REQUIRED, 1, Nsf_ConvertTo_Boolean, NULL,NULL,"boolean",NULL,NULL,NULL,NULL,NULL}, + {"-verbose", 0, 1, Nsf_ConvertTo_Boolean, NULL,NULL,"boolean",NULL,NULL,NULL,NULL,NULL}} +}, {"::nsf::relation::get", NsfRelationGetCmdStub, 2, { {"object", NSF_ARG_REQUIRED, 1, Nsf_ConvertTo_Object, NULL,NULL,"object",NULL,NULL,NULL,NULL,NULL}, {"type", NSF_ARG_REQUIRED|NSF_ARG_IS_ENUMERATION, 1, ConvertToRelationtype, NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL}} Index: generic/nsfAPI.nxdocindex =================================================================== diff -u -r3016e6466668218392140bc884fa8bf489721eda -rc5f2227387dec2a5c0af9b36dc1ebc8578d6603e --- generic/nsfAPI.nxdocindex (.../nsfAPI.nxdocindex) (revision 3016e6466668218392140bc884fa8bf489721eda) +++ generic/nsfAPI.nxdocindex (.../nsfAPI.nxdocindex) (revision c5f2227387dec2a5c0af9b36dc1ebc8578d6603e) @@ -4,6 +4,8 @@ set ::nxdoc::include(::nsf::__db_show_obj) 0 set ::nxdoc::include(::nsf::__profile_clear) 0 set ::nxdoc::include(::nsf::__profile_get) 0 +set ::nxdoc::include(::nsf::__profile_get) 0 +set ::nxdoc::include(::nsf::__profile_trace) 0 set ::nxdoc::include(::nsf::__unset_unknown_args) 0 set ::nxdoc::include(::nsf::asm::proc) 0 set ::nxdoc::include(::nsf::configure) 1 Index: generic/nsfInt.h =================================================================== diff -u -r714726da8aa70930a6f1f482e48ab98e4af0b88b -rc5f2227387dec2a5c0af9b36dc1ebc8578d6603e --- generic/nsfInt.h (.../nsfInt.h) (revision 714726da8aa70930a6f1f482e48ab98e4af0b88b) +++ generic/nsfInt.h (.../nsfInt.h) (revision c5f2227387dec2a5c0af9b36dc1ebc8578d6603e) @@ -851,11 +851,16 @@ Tcl_HashTable procData; Tcl_DString traceDs; int depth; + int verbose; } NsfProfile; -# define NSF_PROFILE_CALL(interp, object, methodName) NsfProfileTraceCall(interp, object, methodName) -# define NSF_PROFILE_EXIT(interp, object, methodName) NsfProfileTraceExit(interp, object, methodName) +# define NSF_PROFILE_TIME_DATA struct timeval profile_trt +# define NSF_PROFILE_CALL(interp, object, methodName) \ + gettimeofday(&profile_trt, NULL); \ + NsfProfileTraceCall(interp, object, methodName) +# define NSF_PROFILE_EXIT(interp, object, methodName) NsfProfileTraceExit(interp, object, methodName, &profile_trt) #else +# define NSF_PROFILE_TIME_DATA() # define NSF_PROFILE_CALL(interp, object, methodName) # define NSF_PROFILE_EXIT(interp, object, methodName) #endif @@ -994,8 +999,8 @@ nonnull(1) nonnull(2) nonnull(3); EXTERN void NsfProfileTraceCall(Tcl_Interp *interp, NsfObject *object, const char *methodName) nonnull(1) nonnull(2) nonnull(3); -EXTERN void NsfProfileTraceExit(Tcl_Interp *interp, NsfObject *object, const char *methodName) - nonnull(1) nonnull(2) nonnull(3); +EXTERN void NsfProfileTraceExit(Tcl_Interp *interp, NsfObject *object, const char *methodName, struct timeval *trt) + nonnull(1) nonnull(2) nonnull(3) nonnull(4); EXTERN void NsfProfileTraceCallAppend(Tcl_Interp *interp, const char *label) nonnull(1) nonnull(2); EXTERN void NsfProfileTraceExitAppend(Tcl_Interp *interp, const char *label, double duration) Index: generic/nsfProfile.c =================================================================== diff -u -r453ad27418d60f0ab744ae4ac911bcd5e2505140 -rc5f2227387dec2a5c0af9b36dc1ebc8578d6603e --- generic/nsfProfile.c (.../nsfProfile.c) (revision 453ad27418d60f0ab744ae4ac911bcd5e2505140) +++ generic/nsfProfile.c (.../nsfProfile.c) (revision c5f2227387dec2a5c0af9b36dc1ebc8578d6603e) @@ -85,6 +85,48 @@ /* *---------------------------------------------------------------------- + * NsfProfileTrace -- + * + * Function callable via tcl to control trace behavior. + * + * Results: + * OK + * + * Side effects: + * update RUNTIME_STATE(interp)->doTrace and profilePtr->verbose + * + *---------------------------------------------------------------------- + */ + +int +NsfProfileTrace(Tcl_Interp *interp, int withEnable, int withVerbose) { + NsfRuntimeState *rst; + NsfProfile *profilePtr; + int oldProfileState; + + assert(interp != NULL); + + rst = RUNTIME_STATE(interp); + profilePtr = &rst->profile; + + fprintf(stderr, "trace: withEnable %d withVerbose %d\n", withEnable, withVerbose); + + oldProfileState = rst->doTrace; + rst->doTrace = withEnable; + /* + * Turn automically profiling on&off, when trace is turned on/off + */ + rst->doProfile = withEnable; + + profilePtr->verbose = withVerbose; + Tcl_SetObjResult(interp, Tcl_NewBooleanObj(oldProfileState)); + + return TCL_OK; +} + + +/* + *---------------------------------------------------------------------- * NsfProfileTraceCallAppend, NsfProfileTraceExitAppend -- * * Low level function to add entries to the trace dstring when functions ar @@ -108,6 +150,9 @@ Tcl_DStringInit(&ds); Nsf_DStringPrintf(&ds, "call(%d): %s\n", profilePtr->depth, label); + if (profilePtr->verbose) { + fprintf(stderr, "### %s", ds.string); + } Tcl_DStringAppend(&profilePtr->traceDs, ds.string, ds.length); Tcl_DStringFree(&ds); } @@ -118,12 +163,16 @@ NsfProfile *profilePtr = &rst->profile; Tcl_DString ds; - profilePtr->depth --; - Tcl_DStringInit(&ds); Nsf_DStringPrintf(&ds, "exit(%d): %s %.0f\n", profilePtr->depth, label, duration); + if (profilePtr->verbose) { + fprintf(stderr, "### %s", ds.string); + } Tcl_DStringAppend(&profilePtr->traceDs, ds.string, ds.length); Tcl_DStringFree(&ds); + + profilePtr->depth --; + } /* @@ -147,7 +196,7 @@ void NsfProfileTraceCall(Tcl_Interp *interp, NsfObject *object, const char *methodName) { NsfRuntimeState *rst = RUNTIME_STATE(interp); - + if (rst->doTrace) { Tcl_DString objectLabel; @@ -158,14 +207,19 @@ } void -NsfProfileTraceExit(Tcl_Interp *interp, NsfObject *object, const char *methodName) { +NsfProfileTraceExit(Tcl_Interp *interp, NsfObject *object, const char *methodName, struct timeval *callTime) { NsfRuntimeState *rst = RUNTIME_STATE(interp); if (rst->doTrace) { Tcl_DString objectLabel; + double totalMicroSec; + struct timeval trt; + gettimeofday(&trt, NULL); + totalMicroSec = (trt.tv_sec - callTime->tv_sec) * 1000000 + (trt.tv_usec - callTime->tv_usec); + NsfProfileObjectLabel(&objectLabel, (object), methodName); - NsfProfileTraceExitAppend(interp, Tcl_DStringValue(&objectLabel), 0.0); + NsfProfileTraceExitAppend(interp, Tcl_DStringValue(&objectLabel), totalMicroSec); Tcl_DStringFree(&objectLabel); } } @@ -194,15 +248,15 @@ assert(dsPtr != NULL); assert(obj != NULL); assert(methodName != NULL); - + Tcl_DStringInit(dsPtr); Tcl_DStringAppend(dsPtr, ObjectName(obj), -1); Tcl_DStringAppend(dsPtr, " ", 1); Tcl_DStringAppend(dsPtr, ClassName(obj->cl), -1); Tcl_DStringAppend(dsPtr, " ", 1); Tcl_DStringAppend(dsPtr, methodName, -1); } - + void NsfProfileRecordMethodData(Tcl_Interp *interp, NsfCallStackContent *cscPtr) { NsfRuntimeState *rst = RUNTIME_STATE(interp); @@ -256,11 +310,11 @@ Tcl_DStringAppend(&methodKey, " - - -", 6); } } - + if (rst->doTrace) { NsfProfileTraceExitAppend(interp, Tcl_DStringValue(&objectKey), totalMicroSec); } - + NsfProfileFillTable(&profilePtr->objectData, Tcl_DStringValue(&objectKey), totalMicroSec); NsfProfileFillTable(&profilePtr->methodData, Tcl_DStringValue(&methodKey), totalMicroSec); Tcl_DStringFree(&objectKey);