Index: TODO =================================================================== diff -u -r7f1ad54528440269c6a26b63c1cb0f0d35001e9c -r40c7482e5387a46679c178138aafb18ae5fda265 --- TODO (.../TODO) (revision 7f1ad54528440269c6a26b63c1cb0f0d35001e9c) +++ TODO (.../TODO) (revision 40c7482e5387a46679c178138aafb18ae5fda265) @@ -2344,6 +2344,17 @@ - nsf.c: fix potential crash for epoched cmds - some minor updates for profiling support +- The fix of yesterdays subst reference counting bug triggered an + other problem: If the last arg was "args", the flags array for + checking the need for decr of refcounts was not extended. There are + multiple possible fixes, i have just extended the flags array for + now as well. +- When profiling is activated, perform now a more sane shutdown order, + all hash tables are now correctly freed. +- Improve behavior, when object system creation fails +- Drop function NsfProfilePrint() + + TODO: - serializer: check, why catch is needed for object-level alias Index: generic/gentclAPI.decls =================================================================== diff -u -r663cbc3775577791f4974963c6c44221a82c49ea -r40c7482e5387a46679c178138aafb18ae5fda265 --- generic/gentclAPI.decls (.../gentclAPI.decls) (revision 663cbc3775577791f4974963c6c44221a82c49ea) +++ generic/gentclAPI.decls (.../gentclAPI.decls) (revision 40c7482e5387a46679c178138aafb18ae5fda265) @@ -20,7 +20,6 @@ nsfCmd __db_show_stack NsfShowStackCmd {} nsfCmd __db_run_assertions NsfDebugRunAssertionsCmd {} nsfCmd __profile_clear NsfProfileClearDataStub {} -nsfCmd __profile_print NsfProfilePrintDataStub {} nsfCmd __profile_get NsfProfileGetDataStub {} nsfCmd alias NsfAliasCmd { Index: generic/nsf.c =================================================================== diff -u -r7f1ad54528440269c6a26b63c1cb0f0d35001e9c -r40c7482e5387a46679c178138aafb18ae5fda265 --- generic/nsf.c (.../nsf.c) (revision 7f1ad54528440269c6a26b63c1cb0f0d35001e9c) +++ generic/nsf.c (.../nsf.c) (revision 40c7482e5387a46679c178138aafb18ae5fda265) @@ -484,19 +484,26 @@ if (requiredSize >= PARSE_CONTEXT_PREALLOC) { if (pcPtr->objv == &pcPtr->objv_static[1]) { /* realloc from preallocated memory */ - pcPtr->full_objv = (Tcl_Obj **)ckalloc(sizeof(Tcl_Obj*) * requiredSize); + pcPtr->full_objv = (Tcl_Obj **)ckalloc(sizeof(Tcl_Obj*) * requiredSize); + pcPtr->flags = (int*) ckalloc(sizeof(int) * requiredSize); memcpy(pcPtr->full_objv, &pcPtr->objv_static[0], sizeof(Tcl_Obj*) * PARSE_CONTEXT_PREALLOC); - /*fprintf(stderr, "alloc %d new objv=%p pcPtr %p\n", requiredSize, pcPtr->full_objv, pcPtr);*/ + memcpy(pcPtr->flags, &pcPtr->flags_static[0], sizeof(int) * PARSE_CONTEXT_PREALLOC); + /*fprintf(stderr, "extend %p alloc %d new objv=%p pcPtr %p\n", + pcPtr, requiredSize, pcPtr->full_objv, pcPtr);*/ + pcPtr->status |= NSF_PC_STATUS_FREE_OBJV; } else { /* realloc from mallocated memory */ pcPtr->full_objv = (Tcl_Obj **)ckrealloc((char *)pcPtr->full_objv, sizeof(Tcl_Obj*) * requiredSize); - /*fprintf(stderr, "realloc %d new objv=%p pcPtr %p\n", requiredSize, pcPtr->full_objv, pcPtr);*/ + pcPtr->flags = (int*) ckrealloc((char *)pcPtr->flags, sizeof(int) * requiredSize); + /*fprintf(stderr, "extend %p realloc %d new objv=%p pcPtr %p\n", + pcPtr, requiredSize, pcPtr->full_objv, pcPtr);*/ } pcPtr->objv = &pcPtr->full_objv[1]; } - memcpy(pcPtr->objv + from, source, sizeof(Tcl_Obj *) * (elts)); + memcpy(pcPtr->objv + from, source, sizeof(Tcl_Obj *) * elts); + memset(pcPtr->flags + from, 0, sizeof(int) * elts); pcPtr->objc += elts; /*NsfPrintObjv("AFTER: ", pcPtr->objc, pcPtr->full_objv);*/ @@ -523,30 +530,39 @@ ParseContextRelease(ParseContext *pcPtr) { int status = pcPtr->status; + /*fprintf(stderr, "ParseContextRelease %p status %.6x %d elements\n", + pcPtr, status, pcPtr->objc);*/ + if (status) { if (status & NSF_PC_STATUS_MUST_DECR) { int i; for (i = 0; i < pcPtr->objc-1; i++) { + /*fprintf(stderr, "ParseContextRelease %p check [%d] obj %p refCount %d (%s)\n", + pcPtr, i, pcPtr->objv[i], pcPtr->objv[i]->refCount, ObjStr(pcPtr->objv[i]));*/ if (pcPtr->flags[i] & NSF_PC_MUST_DECR) { + assert(pcPtr->objv[i]->refCount > 0); DECR_REF_COUNT(pcPtr->objv[i]); } } } - /* objv can be separately extended */ + /* + * Objv can be separately extended; also flags are extend when this + * happens. + */ if (status & NSF_PC_STATUS_FREE_OBJV) { /*fprintf(stderr, "ParseContextRelease %p free %p %p\n", pcPtr, pcPtr->full_objv, pcPtr->clientData);*/ ckfree((char *)pcPtr->full_objv); + ckfree((char *)pcPtr->flags); } /* - * If the parameter definition was extended, both clientData and flags are - * extended. + * If the parameter definition was extended at creation time also + * clientData is extended. */ if (status & NSF_PC_STATUS_FREE_CD) { - /*fprintf(stderr, "free clientdata and flags\n");*/ + /*fprintf(stderr, "free clientdata for %p\n", pcPtr);*/ ckfree((char *)pcPtr->clientData); - ckfree((char *)pcPtr->flags); } } } @@ -14386,17 +14402,6 @@ } /* -nsfCmd __profile_print_data NsfProfilePrintDataStub {} -*/ -static int -NsfProfilePrintDataStub(Tcl_Interp *interp) { -#if defined(NSF_PROFILE) - NsfProfilePrintData(interp); -#endif - return TCL_OK; -} - -/* nsfCmd __profile_get_data NsfProfileGetDataStub {} */ static int @@ -14803,24 +14808,13 @@ thecls = PrimitiveCCreate(interp, class, NULL, NULL); /* fprintf(stderr, "CreateObjectSystem created base classes \n"); */ -#if defined(NSF_PROFILE) - NsfProfileInit(interp); -#endif - /* check whether Object and Class creation was successful */ if (!theobj || !thecls) { - int i; if (thecls) PrimitiveCDestroy((ClientData) thecls); if (theobj) PrimitiveCDestroy((ClientData) theobj); - for (i = 0; i < nr_elements(NsfGlobalStrings); i++) { - DECR_REF_COUNT(NsfGlobalObjs[i]); - } - FREE(Tcl_Obj **, NsfGlobalObjs); - FREE(NsfRuntimeState, RUNTIME_STATE(interp)); ObjectSystemFree(interp, osPtr); - return NsfPrintError(interp, "Creation of object system failed"); } @@ -14997,10 +14991,6 @@ /*fprintf(stderr, "+++ call tcl-defined exit handler\n"); */ -#if defined(NSF_PROFILE) - //NsfProfilePrintData(interp); - NsfProfileClearData(interp); -#endif /* * evaluate user-defined exit handler */ @@ -18946,6 +18936,10 @@ } NsfStringIncrFree(&RUNTIME_STATE(interp)->iss); +#if defined(NSF_PROFILE) + NsfProfileFree(interp); +#endif + #if defined(TCL_MEM_DEBUG) TclDumpMemoryInfo(stderr); Tcl_DumpActiveMemory("./nsfActiveMem"); @@ -19052,6 +19046,10 @@ Tcl_Interp_globalNsPtr(interp)->clientData = runtimeState; #endif +#if defined(NSF_PROFILE) + NsfProfileInit(interp); +#endif + RUNTIME_STATE(interp)->doFilters = 1; RUNTIME_STATE(interp)->doCheckResults = 1; RUNTIME_STATE(interp)->doCheckArguments = 1; Index: generic/nsfInt.h =================================================================== diff -u -r7f1ad54528440269c6a26b63c1cb0f0d35001e9c -r40c7482e5387a46679c178138aafb18ae5fda265 --- generic/nsfInt.h (.../nsfInt.h) (revision 7f1ad54528440269c6a26b63c1cb0f0d35001e9c) +++ generic/nsfInt.h (.../nsfInt.h) (revision 40c7482e5387a46679c178138aafb18ae5fda265) @@ -781,8 +781,8 @@ #if defined(NSF_PROFILE) extern void NsfProfileEvaluateData(Tcl_Interp* interp, NsfCallStackContent *cscPtr); -extern void NsfProfilePrintData(Tcl_Interp *interp); extern void NsfProfileInit(Tcl_Interp *interp); +extern void NsfProfileFree(Tcl_Interp *interp); extern void NsfProfileClearData(Tcl_Interp *interp); extern void NsfProfileGetData(Tcl_Interp *interp); extern NsfCallStackContent *NsfCallStackGetTopFrame(Tcl_Interp *interp, Tcl_CallFrame **framePtrPtr); Index: generic/nsfProfile.c =================================================================== diff -u -r7f1ad54528440269c6a26b63c1cb0f0d35001e9c -r40c7482e5387a46679c178138aafb18ae5fda265 --- generic/nsfProfile.c (.../nsfProfile.c) (revision 7f1ad54528440269c6a26b63c1cb0f0d35001e9c) +++ generic/nsfProfile.c (.../nsfProfile.c) (revision 40c7482e5387a46679c178138aafb18ae5fda265) @@ -22,6 +22,21 @@ long count; } NsfProfileData; +/* + *---------------------------------------------------------------------- + * NsfProfileFillTable -- + * + * Insert or Update a keyed entry with provided microseconds and + * update the counts for this entry. + * + * Results: + * None + * + * Side effects: + * Updated or created profile data entry + * + *---------------------------------------------------------------------- + */ static void NsfProfileFillTable(Tcl_HashTable *table, char *keyStr, double totalMicroSec) { NsfProfileData *value; @@ -41,6 +56,24 @@ value->count ++; } +/* + *---------------------------------------------------------------------- + * NsfProfileEvaluateData -- + * + * This function is invoked, when a call of a method ends. It + * records profiling information based on the provided call stack + * content and the caller. In particular, it records the time spent + * in an object (identified with an objectKey) and the time spent + * in the method (using methodKey). + * + * Results: + * None + * + * Side effects: + * Updated or created profile data entries + * + *---------------------------------------------------------------------- + */ void NsfProfileEvaluateData(Tcl_Interp *interp, NsfCallStackContent *cscPtr) { double totalMicroSec; @@ -105,63 +138,21 @@ Tcl_DStringFree(&methodKey); } -static void -NsfProfilePrintTable(Tcl_HashTable *table) { - Tcl_HashEntry *topValueHPtr; +/* + *---------------------------------------------------------------------- + * NsfProfileClearTable -- + * + * Clear all data in a profile table. + * + * Results: + * None + * + * Side effects: + * freed profile information. + * + *---------------------------------------------------------------------- + */ - assert(table); - - do { - NsfProfileData *topValue; - Tcl_HashSearch hSrch; - Tcl_HashEntry *hPtr; - char *topKey = NULL; - - topValueHPtr = NULL; - topValue = NULL; - - for (hPtr = Tcl_FirstHashEntry(table, &hSrch); hPtr; - hPtr = Tcl_NextHashEntry(&hSrch)) { - NsfProfileData *value = (NsfProfileData *) Tcl_GetHashValue(hPtr); - if (value && - (!topValue || (topValue && value->microSec >= topValue->microSec))) { - topValue = value; - topValueHPtr = hPtr; - topKey = Tcl_GetHashKey(table, hPtr); - } - } - - if (topValueHPtr) { - fprintf(stderr, " %15ld %10ld %s\n", topValue->microSec, topValue->count, topKey); - ckfree((char *) topValue); - Tcl_DeleteHashEntry(topValueHPtr); - } - } while (topValueHPtr); -} - -void -NsfProfilePrintData(Tcl_Interp *interp) { - NsfProfile *profilePtr = &RUNTIME_STATE(interp)->profile; - struct timeval trt; - - fprintf(stderr, "------------------------------------------------------------------\n"); - fprintf(stderr, "\nXOTcl Profile Information\n\n"); - fprintf(stderr, "------------------------------------------------------------------\n"); - fprintf(stderr, "Overall Elapsed Time %ld\n", profilePtr->overallTime); - fprintf(stderr, "------------------------------------------------------------------\n"); - fprintf(stderr, " MICROSECONDS COUNT OBJECT-NAME\n"); - NsfProfilePrintTable(&profilePtr->objectData); - fprintf(stderr, "------------------------------------------------------------------\n"); - fprintf(stderr, " MICROSECONDS COUNT (CL/OBJ)->METHOD-NAME\n"); - NsfProfilePrintTable(&profilePtr->methodData); - fprintf(stderr, "------------------------------------------------------------------\n"); - - gettimeofday(&trt, NULL); - profilePtr->startSec = trt.tv_sec; - profilePtr->startUSec = trt.tv_usec; - profilePtr->overallTime = 0; -} - static void NsfProfileClearTable(Tcl_HashTable *table) { Tcl_HashSearch hSrch; @@ -176,6 +167,21 @@ } } +/* + *---------------------------------------------------------------------- + * NsfProfileClearData -- + * + * Flush all data in all profile tables and reset the time + * counters. + * + * Results: + * None + * + * Side effects: + * freed profile information. + * + *---------------------------------------------------------------------- + */ void NsfProfileClearData(Tcl_Interp *interp) { NsfProfile *profilePtr = &RUNTIME_STATE(interp)->profile; @@ -190,6 +196,21 @@ profilePtr->overallTime = 0; } +/* + *---------------------------------------------------------------------- + * NsfProfileGetTable -- + * + * Return the profiling information for the specified profile table + * in form of a Tcl list. + * + * Results: + * Tcl List + * + * Side effects: + * Nne. + * + *---------------------------------------------------------------------- + */ static Tcl_Obj* NsfProfileGetTable(Tcl_Interp *interp, Tcl_HashTable *table) { Tcl_Obj *list = Tcl_NewListObj(0, NULL); @@ -211,6 +232,23 @@ return list; } +/* + *---------------------------------------------------------------------- + * NsfProfileGetData -- + * + * Return recorded profiling information. This function returns a + * list containing (a) the elapsed time since the last clear (or + * init), (b) the cumulative time, (c) the list with the per-object + * data and (d) the list with the method invocation data. + * + * Results: + * Tcl List + * + * Side effects: + * None. + * + *---------------------------------------------------------------------- + */ void NsfProfileGetData(Tcl_Interp *interp) { Tcl_Obj *list = Tcl_NewListObj(0, NULL); @@ -229,22 +267,59 @@ Tcl_SetObjResult(interp, list); } +/* + *---------------------------------------------------------------------- + * NsfProfileInit -- + * + * Initialize the profiling information. This is a one-time only + * operation and initializes the hash table and the timing + * results. The inverse operation is NsfProfileFree() + * + * Results: + * None. + * + * Side effects: + * None. + * + *---------------------------------------------------------------------- + */ void NsfProfileInit(Tcl_Interp *interp) { NsfProfile *profilePtr = &RUNTIME_STATE(interp)->profile; struct timeval trt; - Tcl_InitHashTable(&RUNTIME_STATE(interp)->profile.objectData, - TCL_STRING_KEYS); - Tcl_InitHashTable(&RUNTIME_STATE(interp)->profile.methodData, - TCL_STRING_KEYS); + Tcl_InitHashTable(&profilePtr->objectData, TCL_STRING_KEYS); + Tcl_InitHashTable(&profilePtr->methodData, TCL_STRING_KEYS); gettimeofday(&trt, NULL); profilePtr->startSec = trt.tv_sec; profilePtr->startUSec = trt.tv_usec; profilePtr->overallTime = 0; } +/* + *---------------------------------------------------------------------- + * NsfProfileFree -- + * + * Free all profiling information. This is a one-time only + * operation only. The inverse operation is NsfProfileInit(). + * + * Results: + * None. + * + * Side effects: + * None. + * + *---------------------------------------------------------------------- + */ +void +NsfProfileFree(Tcl_Interp *interp) { + NsfProfile *profilePtr = &RUNTIME_STATE(interp)->profile; + + NsfProfileClearData(interp); + Tcl_DeleteHashTable(&profilePtr->objectData); + Tcl_DeleteHashTable(&profilePtr->methodData); +} #endif /* Index: generic/tclAPI.h =================================================================== diff -u -r7f1ad54528440269c6a26b63c1cb0f0d35001e9c -r40c7482e5387a46679c178138aafb18ae5fda265 --- generic/tclAPI.h (.../tclAPI.h) (revision 7f1ad54528440269c6a26b63c1cb0f0d35001e9c) +++ generic/tclAPI.h (.../tclAPI.h) (revision 40c7482e5387a46679c178138aafb18ae5fda265) @@ -243,7 +243,6 @@ static int NsfProcCmdStub(ClientData clientData, Tcl_Interp *interp, int objc, Tcl_Obj *CONST objv []); static int NsfProfileClearDataStubStub(ClientData clientData, Tcl_Interp *interp, int objc, Tcl_Obj *CONST objv []); static int NsfProfileGetDataStubStub(ClientData clientData, Tcl_Interp *interp, int objc, Tcl_Obj *CONST objv []); -static int NsfProfilePrintDataStubStub(ClientData clientData, Tcl_Interp *interp, int objc, Tcl_Obj *CONST objv []); static int NsfQualifyObjCmdStub(ClientData clientData, Tcl_Interp *interp, int objc, Tcl_Obj *CONST objv []); static int NsfRelationCmdStub(ClientData clientData, Tcl_Interp *interp, int objc, Tcl_Obj *CONST objv []); static int NsfSelfCmdStub(ClientData clientData, Tcl_Interp *interp, int objc, Tcl_Obj *CONST objv []); @@ -329,7 +328,6 @@ static int NsfProcCmd(Tcl_Interp *interp, int withAd, Tcl_Obj *procName, Tcl_Obj *arguments, Tcl_Obj *body); static int NsfProfileClearDataStub(Tcl_Interp *interp); static int NsfProfileGetDataStub(Tcl_Interp *interp); -static int NsfProfilePrintDataStub(Tcl_Interp *interp); static int NsfQualifyObjCmd(Tcl_Interp *interp, Tcl_Obj *objectName); static int NsfRelationCmd(Tcl_Interp *interp, NsfObject *object, int relationtype, Tcl_Obj *value); static int NsfSelfCmd(Tcl_Interp *interp); @@ -416,7 +414,6 @@ NsfProcCmdIdx, NsfProfileClearDataStubIdx, NsfProfileGetDataStubIdx, - NsfProfilePrintDataStubIdx, NsfQualifyObjCmdIdx, NsfRelationCmdIdx, NsfSelfCmdIdx, @@ -1377,22 +1374,6 @@ } static int -NsfProfilePrintDataStubStub(ClientData clientData, Tcl_Interp *interp, int objc, Tcl_Obj *CONST objv[]) { - (void)clientData; - - - - if (objc != 1) { - return ArgumentError(interp, "too many arguments:", - method_definitions[NsfProfilePrintDataStubIdx].paramDefs, - NULL, objv[0]); - } - - return NsfProfilePrintDataStub(interp); - -} - -static int NsfQualifyObjCmdStub(ClientData clientData, Tcl_Interp *interp, int objc, Tcl_Obj *CONST objv[]) { (void)clientData; @@ -2312,9 +2293,6 @@ {"::nsf::__profile_get", NsfProfileGetDataStubStub, 0, { {NULL, 0, 0, NULL, NULL,NULL,NULL,NULL,NULL,NULL,NULL}} }, -{"::nsf::__profile_print", NsfProfilePrintDataStubStub, 0, { - {NULL, 0, 0, NULL, NULL,NULL,NULL,NULL,NULL,NULL,NULL}} -}, {"::nsf::qualify", NsfQualifyObjCmdStub, 1, { {"objectName", NSF_ARG_REQUIRED, 0, ConvertToTclobj, NULL,NULL,NULL,NULL,NULL,NULL,NULL}} },