Profiling ferite scripts

builder/builder_main.c

@@ -528,7 +528,7 @@ void builder_process_closed_function( FeriteScript *script, FeriteFunction *fnc,
 
     if( (buf = strrchr( native_info->file, '/' )) != NULL )
       buf++;
-    fprintf( target, "#line %d \"%s\"\n", native_info->line, 
+    fprintf( target, "#line %d \"%s\"\n", fnc->line,
 		ferite_replace_string( (buf != NULL ? buf : native_info->file), "\\", "\\\\" ) );
     fprintf( target, "%s\n   }\n   FE_RETURN_VOID;\n   self = NULL;\n}\n\n", native_info->code );
     ferite_stack_pop( FE_NoScript, current_module->name_stack );
@@ -649,7 +649,7 @@ void builder_process_open_function( FeriteScript *script, FeriteFunction *fnc, c
 
     if( (buf = strrchr( native_info->file, '/' )) != NULL )
       buf++;
-    fprintf( target, "#line %d \"%s\"\n", native_info->line,  
+    fprintf( target, "#line %d \"%s\"\n", fnc->line,
 		ferite_replace_string( (buf != NULL ? buf : native_info->file), "\\", "\\\\" ) );
     fprintf( target, "%s\n   }\n   FE_RETURN_VOID;\n   self = NULL;\n", native_info->code );
     if( fnc->klass != NULL && !fnc->is_static )

configure.ac.stub

@@ -130,6 +130,19 @@ AC_ARG_ENABLE( autoload-core,
 
 AC_SUBST(debugdefs)
 
+profile_defs=""
+AC_MSG_CHECKING( for profiling support )
+AC_ARG_ENABLE( profile,
+  [  --enable-profile          enable line and function profiling within ferite [default=no]],
+  echo "yes"; profile_defs="-DFERITE_PROFILE";
+  echo "**************************************************";
+  echo "* PROFILE SUPPORT ENABLED                        *";
+  echo "**************************************************";
+  AC_DEFINE([FERITE_PROFILE], 1, [Whether we are compiling ferite with profiling support mode])
+  ,
+  echo "no"; )
+AC_SUBST(profile_defs)
+
 AC_CHECK_LIB(xml2, xmlParseDocument, 
   [gotxml=yes],
   [gotxml=no;

docs/profile.txt

@@ -0,0 +1,42 @@
+Introduction
+------------
+
+  "Let there be profilers"
+	  - unknown
+
+Currently ferite support for profiling is enabled/disabled at compile time for
+the obvious performance overheads associated with keeping the profiling data
+during runtime. The configure switch for this is "--enable-profile"
+
+Enabling profiling support
+--------------------------
+
+  $ ./configure --enable-profile
+
+Profiling a ferite script
+-------------------------
+
+A ferite script to be profiled must be free of errors and exceptions otherwise
+the profiling data will be unavailable or incorrect.
+
+  $ ferite --fe-profile=foo.json foo.fe
+
+The above will run and profile the script foo.fe. The profiling data is saved
+in foo.json. The fprof[1] tool can be used to generate an html report from the
+profiling data and open the result in a browser (see fprof -h):
+
+  $ fprof foo.json
+
+[1] https://github.com/cention-nazri/fprof
+
+Caveats
+-------
+
+1. Tested only on linux.
+2. Does not support profiling in multithreaded environment.
+3. When run under mod_ferite, with FeriteCache on, the ferite script that is
+   loaded from the cache will have wrong line number information for its
+   !__start__ function. Reason: !__start__() function is not cached and
+   ferite_do_function_start() does a ferite_lexer_jump() for cached functions
+   which voids ferite_scanner_lineno because YY_LESS_LINENO is defined to do
+   nothing (maybe).

ferite-config.in

@@ -42,7 +42,7 @@ while test $# -gt 0; do
       if test @includedir@ != /usr/include ; then
         includes=-I@includedir@
       fi
-      echo $includes @debugdefs@ @thread_defs@ @gc_defs@ 
+      echo $includes @debugdefs@ @thread_defs@ @gc_defs@ @profile_defs@
       ;;
     --libs)
       libdirs=-L@libdir@

include/ferite.h

@@ -81,6 +81,13 @@ FERITE_API int ferite_get_parameters( FeriteVariable **list, int num_args, ... )
 FERITE_API int ferite_get_parameter_count( FeriteVariable **list );
 FERITE_API void *ferite_get_parameter( FeriteVariable **list, int num );
 FERITE_API int ferite_get_required_parameter_list_size( FeriteScript *script, FeriteFunction *function );
+
+#ifdef FERITE_PROFILE
+FERITE_API void ferite_profile_toggle( int state );
+FERITE_API void ferite_profile_set_save_at_exit();
+FERITE_API void ferite_profile_save();
+FERITE_API void ferite_profile_set_filename_format(const char *filename);
+#endif
 
    /* macros to cover internal functions */
 #define fe_new_lng( name, val )             ferite_create_number_long_variable( script, name, val, FE_ALLOC )
@@ -197,6 +204,9 @@ FERITE_API int ferite_get_required_parameter_list_size( FeriteScript *script, Fe
 #include <ferite/ferror.h>
 #include <ferite/farray.h>
 #include <ferite/fbuffer.h>
+#ifdef FERITE_PROFILE
+#include <ferite/fprofile.h>
+#endif
 
 #include <ferite/fobj.h> /* As this is the native class 'Obj' we need the macros here for compilation!*/    
 

include/ferite/Makefile.am

@@ -8,6 +8,7 @@ feincludes_DATA = \
         fopcode.h \
            fops.h \
         fparser.h \
+       fprofile.h \
            freq.h \
          fstack.h \
        fstructs.h \

include/ferite/fcompile.h

@@ -195,7 +195,7 @@ FeriteOp *ferite_do_get_current_op();
 	exec.variable_list = NULL;      \
 	exec.stack = NULL;              \
 	exec.parent = script->gc_stack; \
-	exec.line = (FUNCTION->native_information ? FUNCTION->native_information->line : 0); \
+	exec.line = FUNCTION->line; \
 	script->gc_stack = &exec
 
 #define EXTERNAL_EXIT()             \

include/ferite/fglobals.h

@@ -41,6 +41,9 @@ FERITE_API int ferite_hide_mem_use;
 FERITE_API int ferite_use_mm_with_pcre;
 FERITE_API int ferite_is_strict;
 FERITE_API int ferite_show_partial_implementation;
+#ifdef FERITE_PROFILE
+FERITE_API int ferite_profile_enabled;
+#endif
 FERITE_API FeriteVariable *ferite_ARGV;
 
 FERITE_API void  (*ferite_memory_init)(void);

include/ferite/fprofile.h

@@ -0,0 +1,18 @@
+#ifndef __FERITE_PROFILE_H__
+#define __FERITE_PROFILE_H__
+
+#ifdef FERITE_PROFILE
+#include <time.h>
+
+extern int ferite_profile_enabled;
+
+struct timespec ferite_profile_function_begin(FeriteScript *script, void *container, FeriteFunction *function, FeriteProfileFunction **fpf);
+struct timespec ferite_profile_function_end(FeriteScript *script, FeriteProfileFunction *fpf, int end_line, struct timespec *begin_ts);
+struct timespec ferite_profile_line_begin(FeriteScript *script, const char *filename, const size_t line);
+void ferite_profile_line_end(FeriteScript *script, const char *filename, const size_t line, struct timespec *begin_ts);
+FeriteProfileFunction *ferite_profile_get_function_profile(FeriteScript *script, void *container, FeriteFunction *function);
+void ferite_profile_set_caller(FeriteScript *script, void *container, FeriteFunction *function);
+void ferite_profile_add_caller(FeriteProfileFunction *callee, FeriteProfileFunction *caller, int caller_line, struct timespec duration);
+
+#endif /* FERITE_PROFILE */
+#endif /* __FERITE_PROFILE_H__ */

include/ferite/fstructs.h

@@ -70,6 +70,12 @@ typedef struct _ferite_compile_record              FeriteCompileRecord;
 typedef struct _ferite_bk_req                      FeriteBkRequest;
 typedef struct _ferite_variable_accessors          FeriteVariableAccessors;
 typedef struct _ferite_variable_subtype            FeriteVariableSubType;
+#ifdef FERITE_PROFILE
+typedef struct _ferite_profile_function_caller     FeriteProfileFunctionCaller;
+typedef struct _ferite_profile_function            FeriteProfileFunction;
+typedef struct _ferite_profile_line_entry          FeriteProfileLineEntry;
+typedef struct _ferite_profile_entry               FeriteProfileEntry;
+#endif
 
 typedef void (*FeriteVariableGetAccessor)(FeriteScript*,FeriteVariable*);
 typedef void (*FeriteVariableSetAccessor)(FeriteScript*,FeriteVariable*,FeriteVariable*);
@@ -258,7 +264,6 @@ struct _ferite_function_native_information /* Stores the native code info for bu
 {
     char *code;   /* The code in the block */
     char *file;   /* The file it was declared in */
-    int   line;   /* The line it was declared on */
 };
 
 struct _ferite_function  /* Encapsulate a native and script function */
@@ -268,6 +273,7 @@ struct _ferite_function  /* Encapsulate a native and script function */
     FeriteVariable         *(*fncPtr)( FeriteScript*,void*,FeriteObject*,FeriteFunction*,FeriteVariable**);
                                        /* If it is native, it's function pointer */
     FeriteFunctionNative   *native_information; /* The native infomation about the function */
+    int                    line;       /* The line it was declared on */
     void                   *odata;     /* If we happen to have any native data */
     int                     arg_count; /* The number of arguments in the signature */
     char                    is_static; /* If the function is a static class method */
@@ -429,6 +435,9 @@ struct _ferite_script
 
 	FeriteAMT          *globals;
 	FeriteAMT          *types;
+#ifdef FERITE_PROFILE
+	FeriteProfileFunction *caller;
+#endif
 };
 
 struct _ferite_script_attached_data 
@@ -518,4 +527,43 @@ struct _ferite_compile_record /* Used in the compiler */
 	int want_container_finish;
 };
 
+#ifdef FERITE_PROFILE
+struct _ferite_profile_function_caller {
+	FeriteProfileFunction *caller;
+	int caller_line;
+	size_t frequency;
+	struct timespec total_duration;
+};
+
+struct _ferite_profile_function {
+	char *filename;
+	char *container; /* namespace or class fqn */
+	char *name;
+	int is_native;
+	size_t ncalls;
+	int start_line;
+	int end_line;
+	int calling_line;
+	struct timespec exclusive_duration;
+	struct timespec inclusive_duration;
+	FeriteHash *callers;
+};
+
+struct _ferite_profile_line_entry {
+	unsigned int ncalls;
+	struct timespec total_duration;
+	FeriteHash *functions; /* not null means this line has one or more function definitions */
+};
+
+struct _ferite_profile_entry {
+	char *filename;
+	int is_file;
+	unsigned int filename_len;
+	size_t line_count;
+	FeriteProfileLineEntry *lines; /* 1-based indexing */
+
+	FeriteProfileEntry *next; // next in hash table
+};
+#endif /* FERITE_PROFILE */
+
 #endif /* __FERITE_STRUCTS_H__ */

src/Makefile.am

@@ -12,7 +12,7 @@ LDFLAGS		     = -L${prefix}/lib -lm
 
 INCLUDES	     = -I$(top_srcdir) -I$(top_srcdir)/libs/aphex/include -I$(top_srcdir)/libs/triton/include -I${top_srcdir}/include -I${prefix}/include -I$(includedir) -I${top_srcdir}/include/ferite/ @pcre_cflags@
 
-DEFS                 = @debugdefs@ @thread_defs@ @gc_defs@
+DEFS                 = @debugdefs@ @thread_defs@ @gc_defs@ @profile_defs@
 
 lib_LTLIBRARIES      = libferite.la
 
@@ -31,6 +31,7 @@ ferite_gc_generation.c \
       ferite_execute.c \
       ferite_scanner.c \
       ferite_globals.c \
+      ferite_profile.c \
        ferite_script.c \
        ferite_parser.c \
        ferite_opcode.c \

src/ferite.c

@@ -60,6 +60,7 @@ int ferite_pow_lookup[32];
  *			  --fe-use-classic - this will tell ferite to use malloc/free rather than the jedi memory manager<nl/>
  *			  --fe-debug - tell ferite to dump debug out to stdout, warning: this will produce a lot of output, ferite also has to be compiled with debugging support.<nl/>
  *			  --fe-show-mem-use - tell ferite to dump to stdout a set of memory statistics, this is useful for detecting leaks<nl/>
+ *			  --fe-profile=&lt;file.json&gt; - enable and save profiling data to &lt;file.json&gt;. Date and time formatting specifications as understood by strftime(3) is supported for &lt;file.json&gt;. Requires compile time switch -DFERITE_PROFILE<nl/>
  *			  <nl/>
  *			  This function can be called multiple times without fear - it will only set things up
  *			  if they are needed.
@@ -70,6 +71,9 @@ int ferite_init( int argc, char **argv )
 {
 	int i = 0;
 	int wantDebugBanner = FE_TRUE;
+#ifdef FERITE_PROFILE
+	char *profile_filename_pattern = NULL;
+#endif
 
 	FE_ENTER_FUNCTION;
 
@@ -148,6 +152,17 @@ int ferite_init( int argc, char **argv )
 					wantDebugBanner = FE_FALSE;
 				if( strcmp( argv[i], "--fe-show-partial-implementation") == 0 )
 					ferite_show_partial_implementation = FE_TRUE;
+				if( strncmp( argv[i], "--fe-profile", 12) == 0) {
+#ifdef FERITE_PROFILE
+					if (strlen(argv[i]) <= strlen("--fe-profile=")) {
+						fprintf( stderr, "--fe-profile needs argument: --fe-profile=filename\n");
+						exit(1);
+					}
+					profile_filename_pattern = argv[i] + 13;
+#else
+					fprintf( stderr, "Warning: profiling was not enabled at compile time.\n" );
+#endif
+				}
 			}
 		}
 
@@ -194,6 +209,13 @@ int ferite_init( int argc, char **argv )
 			FE_LEAVE_FUNCTION( ferite_is_initialised );
 		}
 
+#ifdef FERITE_PROFILE
+		if (profile_filename_pattern != NULL) {
+		   ferite_profile_set_filename_format(profile_filename_pattern);
+		   ferite_profile_toggle(FE_TRUE);
+		}
+#endif
+
 		ferite_init_compiler();
 		ferite_init_regex();
 		ferite_set_script_argv( 0, NULL );
@@ -384,6 +406,7 @@ void ferite_show_help()
 	printf( " --fe-use-classic \t	 Run w/ alternate MM mode. (enables allocation tracking; will cause slow downs)\n" );
 	printf( " --fe-use-std-gc  \t	 Run w/ simple GC mode. (will cause slow downs)\n" );
 	printf( " --fe-show-mem-use\t	 Report memory use at script end.\n" );
+	printf( " --fe-profile=<file.json>\t Enable and save profiling data to <file.json> (may include strftime(3) formatters, and additionally %%i for the process id).\n" );
 	printf( " --fe-use-mm-with-pcre\t Use PCRE [Regular Expression Engine] with ferite's MM\n" );
 	printf( "\n MM = Memory Manager\n" );
 	FE_LEAVE_FUNCTION( NOWT );

src/ferite_compile.c

@@ -937,6 +937,7 @@ void ferite_do_function_header( char *name, int is_static, int is_native, int is
 	}
 
 	new_function = ferite_create_internal_function( CURRENT_SCRIPT, real_function_name );
+	new_function->line = ferite_scanner_lineno;
 	new_function->bytecode->filename = fstrdup( (ferite_scanner_file == NULL ? "" : ferite_scanner_file) );
 	new_function->is_static = is_static;
 	new_function->state = FE_ITEM_IS_PUBLIC;
@@ -1103,7 +1104,7 @@ void ferite_do_function_native_block( char *code, char *file, int line )
 	ptr = fmalloc_ngc( sizeof(FeriteFunctionNative) );
 	ptr->code = NULL;
 	ptr->file = fstrdup( file );
-	ptr->line = line;
+	CURRENT_FUNCTION->line = line;
 	CURRENT_FUNCTION->native_information = ptr;
 
 	if( ferite_keep_native_function_data == 1 )