Index: generic/nsf.c =================================================================== diff -u -r74d126b541dc8d342bd39072028e4062b17aee09 -r55c89d7890cc910efd0909b70b074ebf896ce55f --- generic/nsf.c (.../nsf.c) (revision 74d126b541dc8d342bd39072028e4062b17aee09) +++ generic/nsf.c (.../nsf.c) (revision 55c89d7890cc910efd0909b70b074ebf896ce55f) @@ -24162,17 +24162,18 @@ cmd __profile_trace NsfProfileTraceStub { {-argName "-enable" -required 1 -nrargs 1 -type boolean} {-argName "-verbose" -required 0 -nrargs 1 -type boolean} + {-argName "-dontsave" -required 0 -nrargs 1 -type boolean} } */ -static int NsfProfileTraceStub(Tcl_Interp *interp, int withEnable, int withVerbose) +static int NsfProfileTraceStub(Tcl_Interp *interp, int withEnable, int withVerbose, int withDontsave) NSF_nonnull(1); static int -NsfProfileTraceStub(Tcl_Interp *interp, int withEnable, int withVerbose) { +NsfProfileTraceStub(Tcl_Interp *interp, int withEnable, int withVerbose, int withDontsave) { assert(interp != NULL); #if defined(NSF_PROFILE) - NsfProfileTrace(interp, withEnable, withVerbose); + NsfProfileTrace(interp, withEnable, withVerbose, withDontsave); #endif return TCL_OK; } Index: generic/nsfAPI.decls =================================================================== diff -u -rf31c1a01c6a389f693b8db0f2204cbb46180fef1 -r55c89d7890cc910efd0909b70b074ebf896ce55f --- generic/nsfAPI.decls (.../nsfAPI.decls) (revision f31c1a01c6a389f693b8db0f2204cbb46180fef1) +++ generic/nsfAPI.decls (.../nsfAPI.decls) (revision 55c89d7890cc910efd0909b70b074ebf896ce55f) @@ -59,7 +59,8 @@ cmd __profile_get NsfProfileGetDataStub {} cmd __profile_trace NsfProfileTraceStub { {-argName "-enable" -required 1 -nrargs 1 -type boolean} - {-argName "-verbose" -required 0 -nrargs 1 -type boolean} + {-argName "-verbose" -required 0 -nrargs 1 -type boolean} + {-argName "-dontsave" -required 0 -nrargs 1 -type boolean} } cmd __unset_unknown_args NsfUnsetUnknownArgsCmd {} Index: generic/nsfAPI.h =================================================================== diff -u -rf31c1a01c6a389f693b8db0f2204cbb46180fef1 -r55c89d7890cc910efd0909b70b074ebf896ce55f --- generic/nsfAPI.h (.../nsfAPI.h) (revision f31c1a01c6a389f693b8db0f2204cbb46180fef1) +++ generic/nsfAPI.h (.../nsfAPI.h) (revision 55c89d7890cc910efd0909b70b074ebf896ce55f) @@ -646,7 +646,7 @@ NSF_nonnull(1); static int NsfProfileGetDataStub(Tcl_Interp *interp) NSF_nonnull(1); -static int NsfProfileTraceStub(Tcl_Interp *interp, int withEnable, int withVerbose) +static int NsfProfileTraceStub(Tcl_Interp *interp, int withEnable, int withVerbose, int withDontsave) NSF_nonnull(1); static int NsfRelationGetCmd(Tcl_Interp *interp, NsfObject *object, int type) NSF_nonnull(1) NSF_nonnull(2); @@ -2300,9 +2300,10 @@ &pc) == TCL_OK)) { int withEnable = (int )PTR2INT(pc.clientData[0]); int withVerbose = (int )PTR2INT(pc.clientData[1]); + int withDontsave = (int )PTR2INT(pc.clientData[2]); assert(pc.status == 0); - return NsfProfileTraceStub(interp, withEnable, withVerbose); + return NsfProfileTraceStub(interp, withEnable, withVerbose, withDontsave); } else { @@ -3735,9 +3736,10 @@ {"::nsf::__profile_get", NsfProfileGetDataStubStub, 0, { {NULL, 0, 0, NULL, NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL}} }, -{"::nsf::__profile_trace", NsfProfileTraceStubStub, 2, { +{"::nsf::__profile_trace", NsfProfileTraceStubStub, 3, { {"-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}} + {"-verbose", 0, 1, Nsf_ConvertTo_Boolean, NULL,NULL,"boolean",NULL,NULL,NULL,NULL,NULL}, + {"-dontsave", 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}, Index: generic/nsfInt.h =================================================================== diff -u -ra792884dc0eb00b1d1c7da088acfad81496f28da -r55c89d7890cc910efd0909b70b074ebf896ce55f --- generic/nsfInt.h (.../nsfInt.h) (revision a792884dc0eb00b1d1c7da088acfad81496f28da) +++ generic/nsfInt.h (.../nsfInt.h) (revision 55c89d7890cc910efd0909b70b074ebf896ce55f) @@ -851,13 +851,16 @@ Tcl_DString traceDs; int depth; int verbose; + int inmemory; + } NsfProfile; # 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) + NsfProfileTraceCall(interp, object, NULL, methodName) +# define NSF_PROFILE_EXIT(interp, object, methodName) \ + NsfProfileTraceExit(interp, object, NULL, methodName, &profile_trt) #else # define NSF_PROFILE_TIME_DATA # define NSF_PROFILE_CALL(interp, object, methodName) @@ -993,14 +996,14 @@ EXTERN void NsfProfileFree(Tcl_Interp *interp) nonnull(1); EXTERN void NsfProfileClearData(Tcl_Interp *interp) nonnull(1); EXTERN void NsfProfileGetData(Tcl_Interp *interp) nonnull(1); -EXTERN int NsfProfileTrace(Tcl_Interp *interp, int withEnable, int withVerbose); +EXTERN int NsfProfileTrace(Tcl_Interp *interp, int withEnable, int withVerbose, int withInmemory); -EXTERN void NsfProfileObjectLabel(Tcl_DString *dsPtr, NsfObject *obj, const char *methodName) - 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, struct timeval *trt) - nonnull(1) nonnull(2) nonnull(3) nonnull(4); +EXTERN void NsfProfileObjectLabel(Tcl_DString *dsPtr, NsfObject *obj, NsfClass *cl, const char *methodName) + nonnull(1) nonnull(2) nonnull(4); +EXTERN void NsfProfileTraceCall(Tcl_Interp *interp, NsfObject *object, NsfClass *cl, const char *methodName) + nonnull(1) nonnull(2) nonnull(4); +EXTERN void NsfProfileTraceExit(Tcl_Interp *interp, NsfObject *object, NsfClass *cl, const char *methodName, struct timeval *trt) + nonnull(1) nonnull(2) nonnull(4) nonnull(5); 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 -rc5f2227387dec2a5c0af9b36dc1ebc8578d6603e -r55c89d7890cc910efd0909b70b074ebf896ce55f --- generic/nsfProfile.c (.../nsfProfile.c) (revision c5f2227387dec2a5c0af9b36dc1ebc8578d6603e) +++ generic/nsfProfile.c (.../nsfProfile.c) (revision 55c89d7890cc910efd0909b70b074ebf896ce55f) @@ -44,6 +44,10 @@ long count; } NsfProfileData; + + + + /* *---------------------------------------------------------------------- * NsfProfileFillTable -- @@ -93,13 +97,15 @@ * OK * * Side effects: - * update RUNTIME_STATE(interp)->doTrace and profilePtr->verbose + * update RUNTIME_STATE(interp)->doTrace + * and profilePtr->verbose + * and profilePtr->inmemory * *---------------------------------------------------------------------- */ int -NsfProfileTrace(Tcl_Interp *interp, int withEnable, int withVerbose) { +NsfProfileTrace(Tcl_Interp *interp, int withEnable, int withVerbose, int withDontsave) { NsfRuntimeState *rst; NsfProfile *profilePtr; int oldProfileState; @@ -109,16 +115,16 @@ 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; + profilePtr->inmemory = (withDontsave == 1) ? 0 : 1; Tcl_SetObjResult(interp, Tcl_NewBooleanObj(oldProfileState)); return TCL_OK; @@ -127,6 +133,42 @@ /* *---------------------------------------------------------------------- + * ReportLine -- + * + * Report a profile line via NsfLog(). Since NsfLog() uses a Tcl function, + * ReportLine has to turn off profiling to avoid recursive profile + * invocation. It is as well necessary to save the interp result. + * + * Results: + * None + * + * Side effects: + * logging + * + *---------------------------------------------------------------------- + */ +static void ReportLine(Tcl_Interp *interp, NsfRuntimeState *rst, const char *line) + nonnull(1) nonnull(2) nonnull(3); + +static void +ReportLine(Tcl_Interp *interp, NsfRuntimeState *rst, const char *line) { + Tcl_Obj *savedResultObj; + + rst->doProfile = 0; + + savedResultObj = Tcl_GetObjResult(interp); + INCR_REF_COUNT(savedResultObj); + + NsfLog(interp, NSF_LOG_NOTICE, line); + + Tcl_SetObjResult(interp, savedResultObj); + DECR_REF_COUNT(savedResultObj); + + rst->doProfile = 1; +} + +/* + *---------------------------------------------------------------------- * NsfProfileTraceCallAppend, NsfProfileTraceExitAppend -- * * Low level function to add entries to the trace dstring when functions ar @@ -149,11 +191,14 @@ profilePtr->depth ++; Tcl_DStringInit(&ds); - Nsf_DStringPrintf(&ds, "call(%d): %s\n", profilePtr->depth, label); + Nsf_DStringPrintf(&ds, "call(%d): %s", profilePtr->depth, label); if (profilePtr->verbose) { - fprintf(stderr, "### %s", ds.string); + ReportLine(interp, rst, ds.string); } - Tcl_DStringAppend(&profilePtr->traceDs, ds.string, ds.length); + if (profilePtr->inmemory) { + Tcl_DStringAppend(&ds, "\n", 1); + Tcl_DStringAppend(&profilePtr->traceDs, ds.string, ds.length); + } Tcl_DStringFree(&ds); } @@ -164,17 +209,70 @@ Tcl_DString ds; Tcl_DStringInit(&ds); - Nsf_DStringPrintf(&ds, "exit(%d): %s %.0f\n", profilePtr->depth, label, duration); + Nsf_DStringPrintf(&ds, "exit(%d): %s %.0f", profilePtr->depth, label, duration); if (profilePtr->verbose) { - fprintf(stderr, "### %s", ds.string); + ReportLine(interp, rst, ds.string); } - Tcl_DStringAppend(&profilePtr->traceDs, ds.string, ds.length); + if (profilePtr->inmemory) { + Tcl_DStringAppend(&ds, "\n", 1); + Tcl_DStringAppend(&profilePtr->traceDs, ds.string, ds.length); + } Tcl_DStringFree(&ds); profilePtr->depth --; +} + +/* + *---------------------------------------------------------------------- + * NsfProfileObjectLabel, NsfProfileMethodLabel -- + * + * Produce a string label for an object or method using in profiling. + * + * Results: + * None + * + * Side effects: + * Initializes and fills the passed DString, + * + *---------------------------------------------------------------------- + */ +static void NsfProfileObjectLabel(Tcl_DString *dsPtr, NsfObject *obj, NsfClass *cl, const char *methodName) + nonnull(1) nonnull(2) nonnull(4); + +static void NsfProfileMethodLabel(Tcl_DString *dsPtr, NsfObject *obj, NsfClass *cl, const char *methodName) + nonnull(1) nonnull(2) nonnull(4); + +void +NsfProfileObjectLabel(Tcl_DString *dsPtr, NsfObject *obj, NsfClass *cl, const char *methodName) { + + 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); } +static void +NsfProfileMethodLabel(Tcl_DString *dsPtr, NsfObject *obj, NsfClass *cl, const char *methodName) { + + assert(dsPtr != NULL); + assert(obj != NULL); + assert(methodName != NULL); + + Tcl_DStringInit(dsPtr); + + if (cl != NULL) { + Tcl_DStringAppend(dsPtr, ObjStr(cl->object.cmdName), -1); + Tcl_DStringAppend(dsPtr, " ", 1); + } + Tcl_DStringAppendElement(dsPtr, methodName); +} + /* *---------------------------------------------------------------------- * NsfProfileTraceCall, NsfProfileTraceExit -- @@ -194,33 +292,55 @@ */ void -NsfProfileTraceCall(Tcl_Interp *interp, NsfObject *object, const char *methodName) { +NsfProfileTraceCall(Tcl_Interp *interp, NsfObject *object, NsfClass *cl, const char *methodName) { NsfRuntimeState *rst = RUNTIME_STATE(interp); if (rst->doTrace) { - Tcl_DString objectLabel; + Tcl_DString ds, traceLabel; - NsfProfileObjectLabel(&objectLabel, (object), methodName); - NsfProfileTraceCallAppend(interp, Tcl_DStringValue(&objectLabel)); - Tcl_DStringFree(&objectLabel); + Tcl_DStringInit(&ds); + Tcl_DStringInit(&traceLabel); + NsfProfileObjectLabel(&ds, object, cl, methodName); + Tcl_DStringAppendElement(&traceLabel, Tcl_DStringValue(&ds)); + Tcl_DStringAppend(&traceLabel, " ", 1); + + Tcl_DStringTrunc(&ds, 0); + NsfProfileMethodLabel(&ds, object, cl, methodName); + Tcl_DStringAppendElement(&traceLabel, Tcl_DStringValue(&ds)); + + NsfProfileTraceCallAppend(interp, Tcl_DStringValue(&traceLabel)); + Tcl_DStringFree(&traceLabel); + Tcl_DStringFree(&ds); } } void -NsfProfileTraceExit(Tcl_Interp *interp, NsfObject *object, const char *methodName, struct timeval *callTime) { +NsfProfileTraceExit(Tcl_Interp *interp, NsfObject *object, NsfClass *cl, const char *methodName, + struct timeval *callTime) { NsfRuntimeState *rst = RUNTIME_STATE(interp); if (rst->doTrace) { - Tcl_DString objectLabel; + Tcl_DString ds, traceLabel; 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), totalMicroSec); - Tcl_DStringFree(&objectLabel); + Tcl_DStringInit(&ds); + + Tcl_DStringInit(&traceLabel); + NsfProfileObjectLabel(&ds, object, cl, methodName); + Tcl_DStringAppendElement(&traceLabel, Tcl_DStringValue(&ds)); + Tcl_DStringAppend(&traceLabel, " ", 1); + + Tcl_DStringTrunc(&ds, 0); + NsfProfileMethodLabel(&ds, object, cl, methodName); + Tcl_DStringAppendElement(&traceLabel, Tcl_DStringValue(&ds)); + + NsfProfileTraceExitAppend(interp, Tcl_DStringValue(&traceLabel), totalMicroSec); + Tcl_DStringFree(&traceLabel); + Tcl_DStringFree(&ds); } } @@ -243,27 +363,12 @@ *---------------------------------------------------------------------- */ void -NsfProfileObjectLabel(Tcl_DString *dsPtr, NsfObject *obj, const char *methodName) { - - 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); double totalMicroSec; NsfObject *obj = cscPtr->self; NsfClass *cl = cscPtr->cl; - Tcl_DString methodKey, objectKey; + Tcl_DString methodKey, objectKey, methodInfo; NsfProfile *profilePtr = &rst->profile; struct timeval trt; @@ -279,46 +384,52 @@ return; } - NsfProfileObjectLabel(&objectKey, obj, cscPtr->methodName); + NsfProfileObjectLabel(&objectKey, obj, NULL, cscPtr->methodName); + Tcl_DStringInit(&methodInfo); Tcl_DStringInit(&methodKey); - Tcl_DStringAppend(&methodKey, (cl != NULL) ? ObjStr(cl->object.cmdName) : ObjStr(obj->cmdName), -1); - Tcl_DStringAppend(&methodKey, " ", 1); - Tcl_DStringAppend(&methodKey, cscPtr->methodName, -1); - if (cl != NULL) { - Tcl_DStringAppend(&methodKey, " method", 7); - } else { - Tcl_DStringAppend(&methodKey, " object-method", 14); + NsfProfileMethodLabel(&methodInfo, obj, cl, cscPtr->methodName); + + if (rst->doTrace) { + Tcl_DString traceKey; + + Tcl_DStringInit(&traceKey); + Tcl_DStringAppendElement(&traceKey, Tcl_DStringValue(&objectKey)); + Tcl_DStringAppend(&traceKey, " ", 1); + Tcl_DStringAppendElement(&traceKey, Tcl_DStringValue(&methodInfo)); + NsfProfileTraceExitAppend(interp, Tcl_DStringValue(&traceKey), totalMicroSec); + Tcl_DStringFree(&traceKey); } + /* + * Append method to object key as needed by statisitics (but not by trace) + */ + Tcl_DStringAppendElement(&objectKey, cscPtr->methodName); + + /* + * Build method key, containing actual method info and caller method info. + */ + Tcl_DStringInit(&methodKey); + Tcl_DStringAppend(&methodKey, "{", 1); + Tcl_DStringAppend(&methodKey, Tcl_DStringValue(&methodInfo), Tcl_DStringLength(&methodInfo)); + Tcl_DStringAppend(&methodKey, "}", 1); + { NsfCallStackContent *cscPtrTop = NsfCallStackGetTopFrame(interp, NULL); if (cscPtrTop != NULL) { - NsfClass *cl = cscPtrTop->cl; - NsfObject *obj = cscPtrTop->self; - - Tcl_DStringAppend(&methodKey, " ", 1); - Tcl_DStringAppend(&methodKey, (cl != NULL) ? ObjStr(cl->object.cmdName) : ObjStr(obj->cmdName), -1); - Tcl_DStringAppend(&methodKey, " ", 1); - Tcl_DStringAppend(&methodKey, cscPtrTop->methodName, -1); - if (cl != NULL) { - Tcl_DStringAppend(&methodKey, " method", 7); - } else { - Tcl_DStringAppend(&methodKey, " object-method", 14); - } + Tcl_DStringAppend(&methodKey, " {", 2); + NsfProfileMethodLabel(&methodKey, cscPtrTop->self, cscPtrTop->cl, cscPtrTop->methodName); + Tcl_DStringAppend(&methodKey, "}", 1); } else { - Tcl_DStringAppend(&methodKey, " - - -", 6); + Tcl_DStringAppend(&methodKey, " {}", 3); } } - 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); Tcl_DStringFree(&methodKey); + Tcl_DStringFree(&methodInfo); }