Index: generic/nsf.c
===================================================================
diff -u -N -rbf951b5e794b88907333c62b9ebfdaf13c2f26dc -re1c25b411ed784b0f32610f04d2d7188f9cca418
--- generic/nsf.c	(.../nsf.c)	(revision bf951b5e794b88907333c62b9ebfdaf13c2f26dc)
+++ generic/nsf.c	(.../nsf.c)	(revision e1c25b411ed784b0f32610f04d2d7188f9cca418)
@@ -7933,7 +7933,7 @@
   resultObj = Tcl_GetObjResult(interp);
   for ( ; cls != NULL; cls = cls->nextPtr) {
     NsfObject *object = (NsfObject *)cls->cl;
-    
+
     if (object != NULL) {
       if (matchObject && object == matchObject) {
         /*
@@ -12317,7 +12317,7 @@
      * for example, self introspection working for the requested dispatch, we
      * introduce a CMETHOD frame.
      */
-    /*fprintf(stderr, "Nsf_PushFrameCsc %s %s\n", ObjectName(object), Tcl_GetCommandName(cmd));*/
+    /*fprintf(stderr, "Nsf_PushFrameCsc %s %s\n", ObjectName(object), Tcl_GetCommandName(interp, cmd));*/
     Nsf_PushFrameCsc(interp, cscPtr, framePtr);
     result = Tcl_NRCallObjProc(interp, Tcl_Command_objProc(cmd), cp, objc, objv);
     Nsf_PopFrameCsc(interp, framePtr);
@@ -13198,6 +13198,8 @@
           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);*/
@@ -13707,7 +13709,10 @@
   object->flags |= NSF_DESTROY_CALLED;
 
   if (CallDirectly(interp, object, NSF_o_destroy_idx, &methodObj)) {
+    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]);
+
   } else {
     result = CallMethod(object, interp, methodObj, 2, NULL,
                         NSF_CM_IGNORE_PERMISSIONS|NSF_CSC_IMMEDIATE|flags);
@@ -16181,6 +16186,15 @@
 
   CheckCStack(interp, "nsfProc", fullMethodName);
 
+#if defined(NSF_PROFILE)
+  if (rst->doTrace) {
+    NsfProfile *profilePtr = &RUNTIME_STATE(interp)->profile;
+
+    profilePtr->depth ++;
+    NsfLog(interp, NSF_LOG_NOTICE, "call(%d): %s", profilePtr->depth, fullMethodName);
+  }
+#endif
+
   /*
    * The code below is derived from the scripted method dispatch and just
    * slightly adapted to remove object dependencies.
@@ -19255,8 +19269,10 @@
       methodObj = NsfGlobalObjs[NSF_CONFIGURE];
     }
     assert(methodObj != NULL);
-    /* methodObjd is just for error reporting */
+    /* 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));
   } else {
     result = CallMethod(object, interp, methodObj, objc+2, objv, NSF_CSC_IMMEDIATE);
   }
@@ -22555,7 +22571,7 @@
           Tcl_SetObjResult(interp, resultObj);
         }
         break;
-        
+
       case InfomethodsubcmdOriginIdx:
         {
           int nrElements;
@@ -24012,7 +24028,7 @@
   if (NSF_DTRACE_CONFIGURE_PROBE_ENABLED()) {
     /* TODO: opts copied from tclAPI.h; maybe make global value? */
     static const char *opts[] = {
-      "debug", "dtrace", "filter", "profile", "softrecreate",
+      "debug", "dtrace", "filter", "profile", "trace", "softrecreate",
       "objectsystems", "keepcmds", "checkresults", "checkarguments", NULL};
     NSF_DTRACE_CONFIGURE_PROBE((char *)opts[configureoption-1], (valueObj != NULL) ? ObjStr(valueObj) : NULL);
   }
@@ -24103,6 +24119,24 @@
     }
     break;
 
+  case ConfigureoptionTraceIdx:
+    Tcl_SetBooleanObj(Tcl_GetObjResult(interp),
+                      (RUNTIME_STATE(interp)->doTrace));
+    if (valueObj != NULL) {
+#if defined(NSF_PROFILE)
+      RUNTIME_STATE(interp)->doTrace = bool;
+      /*
+       * Turn on autormically profiling, when trace is turned on.
+       */
+      if (bool) {
+        RUNTIME_STATE(interp)->doProfile = bool;
+      }
+#else
+      NsfLog(interp, NSF_LOG_WARN, "No profile support compiled in");
+#endif
+    }
+    break;
+
   case ConfigureoptionSoftrecreateIdx:
     Tcl_SetBooleanObj(Tcl_GetObjResult(interp),
                       (RUNTIME_STATE(interp)->doSoftrecreate));
@@ -27816,7 +27850,9 @@
       ((Command *)object->id)->flags == 0 ? ObjectName(object) : "(deleted)");*/
 
     if (CallDirectly(interp, &object->cl->object, NSF_c_dealloc_idx, &methodObj)) {
+      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]);
     } else {
       result = NsfCallMethodWithArgs(interp, (Nsf_Object *)object->cl, methodObj,
                                      object->cmdName, 1, NULL,
@@ -28025,10 +28061,10 @@
   }
 
   for( ; i < objc;  argc = nextArgc, argv = nextArgv, methodName = nextMethodName) {
-    
+
     assert(initString != NULL);
     Tcl_ResetResult(interp);
-    
+
     switch (isdasharg) {
     case SKALAR_DASH:    /* Argument is a skalar with a leading dash */
       { int j;
@@ -28474,8 +28510,9 @@
 
     /* call recreate --> initialization */
     if (CallDirectly(interp, &cl->object, NSF_c_recreate_idx, &methodObj)) {
+      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]);
     } else {
 
       ALLOC_ON_STACK(Tcl_Obj*, objc+3, xov);
@@ -28506,7 +28543,9 @@
      */
 
     if (CallDirectly(interp, &cl->object, NSF_c_alloc_idx, &methodObj)) {
+      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]);
     } else {
       result = CallMethod(cl, interp, methodObj,
                           3, &nameObj, NSF_CSC_IMMEDIATE);
@@ -28732,7 +28771,9 @@
     callDirectly = CallDirectly(interp, &cl->object, NSF_c_create_idx, &methodObj);
 
     if (callDirectly != 0) {
+      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]);
     } else {
       ALLOC_ON_STACK(Tcl_Obj*, objc+3, ov);
 
@@ -28793,7 +28834,9 @@
      */
     if (CallDirectly(interp, object, NSF_o_cleanup_idx, &methodObj)) {
       /*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);
+      NSF_PROFILE_EXIT(interp, object, Nsf_SystemMethodOpts[NSF_o_cleanup_idx]);
     } else {
       /*NsfObjectSystem *osPtr = GetObjectSystem(object);
       fprintf(stderr, "RECREATE calls method cleanup for object %p %s OS %s\n",
Index: generic/nsfAPI.decls
===================================================================
diff -u -N -rcbcfec72376d549a806859c873195cc0ebc9c9ea -re1c25b411ed784b0f32610f04d2d7188f9cca418
--- generic/nsfAPI.decls	(.../nsfAPI.decls)	(revision cbcfec72376d549a806859c873195cc0ebc9c9ea)
+++ generic/nsfAPI.decls	(.../nsfAPI.decls)	(revision e1c25b411ed784b0f32610f04d2d7188f9cca418)
@@ -67,7 +67,7 @@
 }
 
 cmd configure NsfConfigureCmd {
-  {-argName "option" -required 1 -typeName "configureoption" -type "debug|dtrace|filter|profile|softrecreate|objectsystems|keepcmds|checkresults|checkarguments"}
+  {-argName "option" -required 1 -typeName "configureoption" -type "debug|dtrace|filter|profile|trace|softrecreate|objectsystems|keepcmds|checkresults|checkarguments"}
   {-argName "value" -required 0 -type tclobj}
 } {-nxdoc 1}
 cmd colon NsfColonCmd {
Index: generic/nsfAPI.h
===================================================================
diff -u -N -r62beaf105e751bb647d88153700253b4c6723127 -re1c25b411ed784b0f32610f04d2d7188f9cca418
--- generic/nsfAPI.h	(.../nsfAPI.h)	(revision 62beaf105e751bb647d88153700253b4c6723127)
+++ generic/nsfAPI.h	(.../nsfAPI.h)	(revision e1c25b411ed784b0f32610f04d2d7188f9cca418)
@@ -129,12 +129,12 @@
   return result;
 }
   
-enum ConfigureoptionIdx {ConfigureoptionNULL, ConfigureoptionDebugIdx, ConfigureoptionDtraceIdx, ConfigureoptionFilterIdx, ConfigureoptionProfileIdx, ConfigureoptionSoftrecreateIdx, ConfigureoptionObjectsystemsIdx, ConfigureoptionKeepcmdsIdx, ConfigureoptionCheckresultsIdx, ConfigureoptionCheckargumentsIdx};
+enum ConfigureoptionIdx {ConfigureoptionNULL, ConfigureoptionDebugIdx, ConfigureoptionDtraceIdx, ConfigureoptionFilterIdx, ConfigureoptionProfileIdx, ConfigureoptionTraceIdx, ConfigureoptionSoftrecreateIdx, ConfigureoptionObjectsystemsIdx, ConfigureoptionKeepcmdsIdx, ConfigureoptionCheckresultsIdx, ConfigureoptionCheckargumentsIdx};
 
 static int ConvertToConfigureoption(Tcl_Interp *interp, Tcl_Obj *objPtr, Nsf_Param const *pPtr,
 			    ClientData *clientData, Tcl_Obj **outObjPtr) {
   int index, result;
-  static const char *opts[] = {"debug", "dtrace", "filter", "profile", "softrecreate", "objectsystems", "keepcmds", "checkresults", "checkarguments", NULL};
+  static const char *opts[] = {"debug", "dtrace", "filter", "profile", "trace", "softrecreate", "objectsystems", "keepcmds", "checkresults", "checkarguments", NULL};
   (void)pPtr;
   result = Tcl_GetIndexFromObj(interp, objPtr, opts, "configureoption", 0, &index);
   *clientData = (ClientData) INT2PTR(index + 1);
@@ -271,7 +271,7 @@
   {ConvertToMethodproperty, "class-only|call-private|call-protected|redefine-protected|returns|slotobj"},
   {ConvertToRelationtype, "object-mixin|class-mixin|object-filter|class-filter|class|superclass|rootclass"},
   {ConvertToSource, "all|application|system"},
-  {ConvertToConfigureoption, "debug|dtrace|filter|profile|softrecreate|objectsystems|keepcmds|checkresults|checkarguments"},
+  {ConvertToConfigureoption, "debug|dtrace|filter|profile|trace|softrecreate|objectsystems|keepcmds|checkresults|checkarguments"},
   {ConvertToObjectproperty, "initialized|class|rootmetaclass|rootclass|volatile|slotcontainer|hasperobjectslots|keepcallerself|perobjectdispatch"},
   {ConvertToAssertionsubcmd, "check|object-invar|class-invar"},
   {ConvertToParametersubcmd, "default|list|name|syntax|type"},
Index: generic/nsfInt.h
===================================================================
diff -u -N -r9e00fd16244c59971f9d0ee692104eeba4be6cd0 -re1c25b411ed784b0f32610f04d2d7188f9cca418
--- generic/nsfInt.h	(.../nsfInt.h)	(revision 9e00fd16244c59971f9d0ee692104eeba4be6cd0)
+++ generic/nsfInt.h	(.../nsfInt.h)	(revision e1c25b411ed784b0f32610f04d2d7188f9cca418)
@@ -844,7 +844,33 @@
   Tcl_HashTable objectData;
   Tcl_HashTable methodData;
   Tcl_HashTable procData;
+  int depth;
 } NsfProfile;
+
+# define NSF_PROFILE_CALL(interp, object, methodName) \
+  if (RUNTIME_STATE(interp)->doTrace) {	      \
+        Tcl_DString objectLabel; \
+        NsfProfile *profilePtr = &RUNTIME_STATE(interp)->profile; \
+\
+        profilePtr->depth ++; \
+	NsfProfileObjectLabel(&objectLabel, (object), methodName);	\
+        NsfLog(interp, NSF_LOG_NOTICE, "call(%d): %s", profilePtr->depth, Tcl_DStringValue(&objectLabel));\
+        Tcl_DStringFree(&objectLabel);\
+      }
+# define NSF_PROFILE_EXIT(interp, object, methodName) \
+  if (RUNTIME_STATE(interp)->doTrace) {	      \
+        Tcl_DString objectLabel; \
+        NsfProfile *profilePtr = &RUNTIME_STATE(interp)->profile; \
+	Tcl_Obj *resultObj = Tcl_GetObjResult(interp); INCR_REF_COUNT(resultObj); \
+        profilePtr->depth --; \
+	NsfProfileObjectLabel(&objectLabel, (object), methodName);	\
+        NsfLog(interp, NSF_LOG_NOTICE, "exit(%d): %s 0", profilePtr->depth, Tcl_DStringValue(&objectLabel));\
+	Tcl_SetObjResult(interp, resultObj); DECR_REF_COUNT(resultObj); \
+        Tcl_DStringFree(&objectLabel);\
+      }
+#else
+# define NSF_PROFILE_CALL(interp, object, methodName)
+# define NSF_PROFILE_EXIT(interp, object, methodName) 
 #endif
 
 typedef struct NsfRuntimeState {
@@ -886,6 +912,7 @@
   int doFilters;
   int doKeepcmds;
   int doProfile;
+  int doTrace;
   int doSoftrecreate;
   /* keep track of defined filters */
   Tcl_HashTable activeFilterTablePtr;
@@ -975,6 +1002,8 @@
 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 void NsfProfileObjectLabel(Tcl_DString *dsPtr, NsfObject *obj, const char *methodName)
+  nonnull(1) nonnull(2) nonnull(3);
 
 EXTERN NsfCallStackContent *NsfCallStackGetTopFrame(Tcl_Interp *interp, Tcl_CallFrame **framePtrPtr)
   nonnull(1);
Index: generic/nsfProfile.c
===================================================================
diff -u -N -r24571ae44c492c681d3efd2f2d2f5169ad7d6d57 -re1c25b411ed784b0f32610f04d2d7188f9cca418
--- generic/nsfProfile.c	(.../nsfProfile.c)	(revision 24571ae44c492c681d3efd2f2d2f5169ad7d6d57)
+++ generic/nsfProfile.c	(.../nsfProfile.c)	(revision e1c25b411ed784b0f32610f04d2d7188f9cca418)
@@ -102,12 +102,28 @@
  *----------------------------------------------------------------------
  */
 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) {
   double totalMicroSec;
   NsfObject *obj = cscPtr->self;
   NsfClass *cl = cscPtr->cl;
   Tcl_DString methodKey, objectKey;
-  NsfProfile *profile = &RUNTIME_STATE(interp)->profile;
+  NsfRuntimeState *rst = RUNTIME_STATE(interp);
+  NsfProfile *profilePtr = &rst->profile;
   struct timeval trt;
 
   assert(interp != NULL);
@@ -116,18 +132,13 @@
   gettimeofday(&trt, NULL);
 
   totalMicroSec = (trt.tv_sec - cscPtr->startSec) * 1000000 + (trt.tv_usec - cscPtr->startUsec);
-  profile->overallTime += totalMicroSec;
+  profilePtr->overallTime += totalMicroSec;
 
   if (obj->teardown == 0 || !obj->id) {
     return;
   }
 
-  Tcl_DStringInit(&objectKey);
-  Tcl_DStringAppend(&objectKey, ObjectName(obj), -1);
-  Tcl_DStringAppend(&objectKey, " ", 1);
-  Tcl_DStringAppend(&objectKey, ClassName(obj->cl), -1);
-  Tcl_DStringAppend(&objectKey, " ", 1);
-  Tcl_DStringAppend(&objectKey, cscPtr->methodName, -1);
+  NsfProfileObjectLabel(&objectKey, obj, cscPtr->methodName);
 
   Tcl_DStringInit(&methodKey);
   Tcl_DStringAppend(&methodKey, (cl != NULL) ? ObjStr(cl->object.cmdName) : ObjStr(obj->cmdName), -1);
@@ -159,15 +170,21 @@
     }
   }
 
-  NsfProfileFillTable(&profile->objectData, Tcl_DStringValue(&objectKey), totalMicroSec);
-  NsfProfileFillTable(&profile->methodData, Tcl_DStringValue(&methodKey), totalMicroSec);
+  if (rst->doTrace) {
+    NsfLog(interp, NSF_LOG_NOTICE, "exit(%d): %s %.0f", profilePtr->depth, Tcl_DStringValue(&objectKey), totalMicroSec);
+    profilePtr->depth --;
+    //fprintf(stderr, "methodData-data: %s %.2f\n", Tcl_DStringValue(&methodKey), totalMicroSec);
+  }
+  
+  NsfProfileFillTable(&profilePtr->objectData, Tcl_DStringValue(&objectKey), totalMicroSec);
+  NsfProfileFillTable(&profilePtr->methodData, Tcl_DStringValue(&methodKey), totalMicroSec);
   Tcl_DStringFree(&objectKey);
   Tcl_DStringFree(&methodKey);
 }
 
 /*
  *----------------------------------------------------------------------
- * NsfProfileRecordMethodData --
+ * NsfProfileRecordProcData --
  *
  *    This function is invoked, when a call of a nsf::proc. It records
  *    time spent and count per nsf::proc.
@@ -182,7 +199,8 @@
  */
 void
 NsfProfileRecordProcData(Tcl_Interp *interp, char *methodName, long startSec, long startUsec) {
-  NsfProfile *profile = &RUNTIME_STATE(interp)->profile;
+  NsfRuntimeState *rst = RUNTIME_STATE(interp);
+  NsfProfile *profilePtr = &rst->profile;
   double totalMicroSec;
   struct timeval trt;
 
@@ -192,9 +210,14 @@
   gettimeofday(&trt, NULL);
 
   totalMicroSec = (trt.tv_sec - startSec) * 1000000 + (trt.tv_usec - startUsec);
-  profile->overallTime += totalMicroSec;
+  profilePtr->overallTime += totalMicroSec;
 
-  NsfProfileFillTable(&profile->procData, methodName, totalMicroSec);
+  if (rst->doTrace) {
+    NsfLog(interp, NSF_LOG_NOTICE, "exit(%d): %s %.0f", profilePtr->depth, methodName, totalMicroSec);
+    profilePtr->depth --;
+  }
+
+  NsfProfileFillTable(&profilePtr->procData, methodName, totalMicroSec);
 }
 
 /*
@@ -261,6 +284,7 @@
   profilePtr->startSec = trt.tv_sec;
   profilePtr->startUSec = trt.tv_usec;
   profilePtr->overallTime = 0;
+  profilePtr->depth = 0;
 }
 
 /*
@@ -373,6 +397,7 @@
   profilePtr->startSec = trt.tv_sec;
   profilePtr->startUSec = trt.tv_usec;
   profilePtr->overallTime = 0;
+  profilePtr->depth = 0;
 }
 
 /*