diff --git a/builder/builder_main.c b/builder/builder_main.c index 003d62f..3767439 100644 --- a/builder/builder_main.c +++ b/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 ) diff --git a/configure.ac.stub b/configure.ac.stub index 40a8c20..2bc8b6b 100644 --- a/configure.ac.stub +++ b/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; diff --git a/docs/profile.txt b/docs/profile.txt new file mode 100644 index 0000000..dbe26bf --- /dev/null +++ b/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). diff --git a/ferite-config.in b/ferite-config.in index 422c412..0e76ddd 100644 --- a/ferite-config.in +++ b/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@ diff --git a/include/ferite.h b/include/ferite.h index 6e9c136..c4624a6 100644 --- a/include/ferite.h +++ b/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 #include #include +#ifdef FERITE_PROFILE +#include +#endif #include /* As this is the native class 'Obj' we need the macros here for compilation!*/ diff --git a/include/ferite/Makefile.am b/include/ferite/Makefile.am index 9277f4b..1989073 100644 --- a/include/ferite/Makefile.am +++ b/include/ferite/Makefile.am @@ -8,6 +8,7 @@ feincludes_DATA = \ fopcode.h \ fops.h \ fparser.h \ + fprofile.h \ freq.h \ fstack.h \ fstructs.h \ diff --git a/include/ferite/fcompile.h b/include/ferite/fcompile.h index 3765b3f..1730a4b 100644 --- a/include/ferite/fcompile.h +++ b/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() \ diff --git a/include/ferite/fglobals.h b/include/ferite/fglobals.h index 01a53d0..a503cd2 100644 --- a/include/ferite/fglobals.h +++ b/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); diff --git a/include/ferite/fprofile.h b/include/ferite/fprofile.h new file mode 100644 index 0000000..d5ecfc5 --- /dev/null +++ b/include/ferite/fprofile.h @@ -0,0 +1,18 @@ +#ifndef __FERITE_PROFILE_H__ +#define __FERITE_PROFILE_H__ + +#ifdef FERITE_PROFILE +#include + +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__ */ diff --git a/include/ferite/fstructs.h b/include/ferite/fstructs.h index 563ff03..e08dc62 100644 --- a/include/ferite/fstructs.h +++ b/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__ */ diff --git a/src/Makefile.am b/src/Makefile.am index 01c8649..1dd3a8c 100644 --- a/src/Makefile.am +++ b/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 \ diff --git a/src/ferite.c b/src/ferite.c index 6df1b89..b06999b 100644 --- a/src/ferite.c +++ b/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 * --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. * --fe-show-mem-use - tell ferite to dump to stdout a set of memory statistics, this is useful for detecting leaks + * --fe-profile=<file.json> - enable and save profiling data to <file.json>. Date and time formatting specifications as understood by strftime(3) is supported for <file.json>. Requires compile time switch -DFERITE_PROFILE * * 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=\t Enable and save profiling data to (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 ); diff --git a/src/ferite_compile.c b/src/ferite_compile.c index e053130..b7a3179 100644 --- a/src/ferite_compile.c +++ b/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 ) diff --git a/src/ferite_execute.c b/src/ferite_execute.c index 35f7962..c9fde7c 100644 --- a/src/ferite_execute.c +++ b/src/ferite_execute.c @@ -84,6 +84,9 @@ int ferite_script_execute( FeriteScript *script ) FeriteNamespaceBucket *nsb = NULL; FeriteFunction *func = NULL; FeriteVariable *err = NULL, *errstr = NULL, *erno = NULL, *rval = NULL; +#ifdef FERITE_PROFILE + FeriteProfileFunction *callee; +#endif FE_ENTER_FUNCTION; @@ -95,8 +98,22 @@ int ferite_script_execute( FeriteScript *script ) if( nsb != NULL ) { +#ifdef FERITE_PROFILE + struct timespec begin_ts = {0, 0}; +#endif func = nsb->data; + +#ifdef FERITE_PROFILE + if (ferite_profile_enabled) { + begin_ts = ferite_profile_function_begin(script, script->mainns, func, &callee); + } +#endif rval = ferite_script_function_execute( script, script->mainns, NULL, func, NULL ); +#ifdef FERITE_PROFILE + if (ferite_profile_enabled) { + (void) ferite_profile_function_end(script, callee, script->current_op_line, &begin_ts); + } +#endif #ifdef THREAD_SAFE ferite_thread_group_wait( script, script->thread_group ); @@ -175,6 +192,9 @@ FE_NATIVE_FUNCTION( ferite_script_function_execute ) exec.block_depth = 0; exec.parent = script->gc_stack; script->gc_stack = &exec; +#ifdef FERITE_PROFILE + script->caller = NULL; +#endif /*}}}*/ /*{{{ Copy parameter values over to the local variable stack */ @@ -344,6 +364,17 @@ INLINE_OP( ferite_exec_funcall ) int i, j, _arg_count; char *method_name = NULL; void *function_container = NULL; +#ifdef FERITE_PROFILE + struct timespec duration; + struct timespec begin_ts = {0, 0}; + FeriteProfileFunction *caller = NULL; + FeriteProfileFunction *callee = NULL; + int caller_line = -1; + + if (ferite_profile_enabled) { + caller_line = script->current_op_line; + } +#endif /*{{{ Create Parameter List */ FUD(("CREATING PARAMETER LIST.\n")); @@ -366,6 +397,11 @@ INLINE_OP( ferite_exec_funcall ) // FUNCALL FeriteFunction *f = ferite_object_get_function( script, current_recipient, "invoke" ); FUD(( "%s>>> Deliver: Pre: %p\n", ferite_stroflen(' ', (ferite_execute_call_depth*2)), context->new_yield_block )); +#ifdef FERITE_PROFILE + if (ferite_profile_enabled) { + ferite_profile_set_caller(script, container, function); + } +#endif rval = ferite_call_function( script, current_recipient, context->new_yield_block, f, param_list ); FUD(( "%s<<< Deliver: Post: %p\n", ferite_stroflen(' ', (ferite_execute_call_depth*2)),context->new_yield_block )); } @@ -617,6 +653,13 @@ INLINE_OP( ferite_exec_funcall ) if( trgt_function_call != NULL ) { // FUNCALL LOCK_VARIABLE(trgt_function_call); /* lock the method */ + +#ifdef FERITE_PROFILE + if (ferite_profile_enabled) { + caller = ferite_profile_get_function_profile(script, container, function); + begin_ts = ferite_profile_function_begin(script, function_container, trgt_function_call, &callee); + } +#endif if( trgt_function_call->type == FNC_IS_EXTRL ) { if( trgt_function_call->fncPtr != NULL ) { EXTERNAL_ENTER( trgt_function_call ); @@ -624,7 +667,7 @@ INLINE_OP( ferite_exec_funcall ) FE_ENTER_NAMED_FUNCTION( trgt_function_call->name ); if( trgt_function_call->native_information != NULL ) { script->current_op_file = trgt_function_call->native_information->file; - script->current_op_line = trgt_function_call->native_information->line; + script->current_op_line = trgt_function_call->line; } rval = (trgt_function_call->fncPtr)( script, function_container, context->new_yield_block, trgt_function_call, param_list ); FE_LEAVE_NAMED_FUNCTION( trgt_function_call->name ); @@ -638,6 +681,13 @@ INLINE_OP( ferite_exec_funcall ) { rval = ferite_script_function_execute( script, function_container, context->new_yield_block, trgt_function_call, param_list ); } +#ifdef FERITE_PROFILE + if (ferite_profile_enabled) { + duration = ferite_profile_function_end(script, callee, script->current_op_line, &begin_ts); + callee = ferite_profile_get_function_profile(script, container, trgt_function_call); + ferite_profile_add_caller(callee, caller, caller_line, duration); + } +#endif UNLOCK_VARIABLE(trgt_function_call); /* unlock the method */ if( script->error_state != FE_ERROR_THROWN ) { script->current_op_file = function->bytecode->filename; /* we do this because the other function might cause it to change */ @@ -658,6 +708,11 @@ INLINE_OP( ferite_exec_funcall ) ferite_error( script, 0, "%s is not a class, bad luck, try again :)\n", ferite_variable_id_to_str(script,vartwo->type) ); break; } +#ifdef FERITE_PROFILE + if (ferite_profile_enabled) { + ferite_profile_set_caller(script, container, function); + } +#endif rval = (void *)ferite_new_object( script, VAC(vartwo), param_list ); if( script->error_state != FE_ERROR_THROWN ) { script->current_op_file = function->bytecode->filename; /* we do this because the other function might cause it to change */ @@ -738,6 +793,11 @@ INLINE_OP( ferite_exec_pushattr ) FUD(( "%s>>> attribute_missing: Pre: %s: %p\n", ferite_stroflen(' ', (ferite_execute_call_depth*2)), var_name, context->new_yield_block )); str = ferite_str_new( script, var_name, strlen( var_name ), FE_CHARSET_DEFAULT ); pml = ferite_create_parameter_list_from_data( script, "s", str ); +#ifdef FERITE_PROFILE + if (ferite_profile_enabled) { + ferite_profile_set_caller(script, container, function); + } +#endif varone = ferite_call_function( script, VAP(vartwo), context->new_yield_block, trgt_function_call, pml ); ferite_delete_parameter_list( script, pml ); ferite_str_destroy( script, str ); @@ -801,6 +861,11 @@ INLINE_OP( ferite_exec_pushattr ) { str = ferite_str_new( script, var_name, strlen( var_name ), FE_CHARSET_DEFAULT ); pml = ferite_create_parameter_list_from_data( script, "s", str ); +#ifdef FERITE_PROFILE + if (ferite_profile_enabled) { + ferite_profile_set_caller(script, container, function); + } +#endif varone = ferite_call_function( script, VAP(vartwo), context->new_yield_block, trgt_function_call, pml ); ferite_delete_parameter_list( script, pml ); ferite_str_destroy( script, str ); @@ -849,6 +914,11 @@ INLINE_OP( ferite_exec_pushattr ) FUD(( "%s>>> attribute_missing: Pre: %s: %p\n", ferite_stroflen(' ', (ferite_execute_call_depth*2)), var_name, context->new_yield_block )); str = ferite_str_new( script, var_name, strlen( var_name ), FE_CHARSET_DEFAULT ); pml = ferite_create_parameter_list_from_data( script, "s", str ); +#ifdef FERITE_PROFILE + if (ferite_profile_enabled) { + ferite_profile_set_caller(script, container, function); + } +#endif varone = ferite_call_function( script, VAP(vartwo), context->new_yield_block, trgt_function_call, pml ); ferite_delete_parameter_list( script, pml ); ferite_str_destroy( script, str ); @@ -1377,6 +1447,12 @@ FeriteVariable *ferite_script_real_function_execute( FeriteScript *script, void FeriteVariable *return_val = NULL; FeriteOpcodeContext *context, stack_context; int error_op_location = 0, error_array[ERROR_UPPER_BOUND + 1]; +#ifdef FERITE_PROFILE + // NOTE: In this function we profile only line duration + struct timespec begin_ts = {0, 0}; + char profile_filename[PATH_MAX]; + int profile_current_line = -1; +#endif /*}}}*/ FE_ENTER_FUNCTION; @@ -1391,6 +1467,11 @@ FeriteVariable *ferite_script_real_function_execute( FeriteScript *script, void context->current_op_loc++; script->current_op_file = function->bytecode->filename; +#ifdef FERITE_PROFILE + /* Make a copy because by the end of execution script->current_op_file + * might not be pointing to the same file */ + strcpy(profile_filename, script->current_op_file); +#endif FUD(("EXECUTION STARTING\n")); while( context->keep_function_running && script->keep_execution ) @@ -1400,6 +1481,15 @@ FeriteVariable *ferite_script_real_function_execute( FeriteScript *script, void script->current_op_line = current_op->line; exec->block_depth = current_op->block_depth; +#ifdef FERITE_PROFILE + if (ferite_profile_enabled) { + if (profile_current_line != current_op->line) { + profile_current_line = current_op->line; + begin_ts = ferite_profile_line_begin(script, profile_filename, profile_current_line); + } + } +#endif + if( ferite_opcode_table[current_op->OP_TYPE].op != NULL ) return_val = CALL_INLINE_OP((ferite_opcode_table[current_op->OP_TYPE].op)); else @@ -1471,6 +1561,14 @@ FeriteVariable *ferite_script_real_function_execute( FeriteScript *script, void } } +#ifdef FERITE_PROFILE + if (ferite_profile_enabled) { + if ((current_op != NULL && profile_current_line != current_op->line) || + !context->keep_function_running || !script->keep_execution) { + ferite_profile_line_end(script, profile_filename, profile_current_line, &begin_ts); + } + } +#endif if( !context->keep_function_running || !script->keep_execution ) break; @@ -1629,6 +1727,12 @@ FeriteVariable *ferite_call_function( FeriteScript *script, void *container, Fer FeriteFunction *function = NULL; FeriteVariable **plist = NULL; int script_exec_state = 0; +#ifdef FERITE_PROFILE + struct timespec begin_ts = {0, 0}; + struct timespec duration; + FeriteProfileFunction *callee = NULL; + FeriteProfileFunction *caller = NULL; +#endif FE_ENTER_FUNCTION; @@ -1649,6 +1753,12 @@ FeriteVariable *ferite_call_function( FeriteScript *script, void *container, Fer if( ferite_check_params( script, plist, function ) == 1 ) { LOCK_VARIABLE( function ); +#ifdef FERITE_PROFILE + if (ferite_profile_enabled) { + caller = script->caller; + begin_ts = ferite_profile_function_begin(script, container, function, &callee); + } +#endif if( function->type == FNC_IS_EXTRL ) { /* This is used to hook up the execute record */ @@ -1665,6 +1775,15 @@ FeriteVariable *ferite_call_function( FeriteScript *script, void *container, Fer if( script->error_state == FE_ERROR_THROWN ) retval = ferite_create_void_variable( script, "error...", FE_STATIC ); } +#ifdef FERITE_PROFILE + if (ferite_profile_enabled) { + duration = ferite_profile_function_end(script, callee, script->current_op_line, &begin_ts); + if (caller != NULL) { + ferite_profile_add_caller(callee, caller, caller->calling_line, duration); + script->caller = NULL; + } + } +#endif UNLOCK_VARIABLE( function ); break; } diff --git a/src/ferite_function.c b/src/ferite_function.c index 958bd67..bceb208 100644 --- a/src/ferite_function.c +++ b/src/ferite_function.c @@ -536,6 +536,7 @@ FeriteFunction *ferite_function_dup( FeriteScript *script, FeriteFunction *funct else ptr->name = NULL; + ptr->line = function->line; ptr->type = function->type; ptr->is_static = function->is_static; ptr->arg_count = function->arg_count; @@ -567,7 +568,6 @@ FeriteFunction *ferite_function_dup( FeriteScript *script, FeriteFunction *funct ptr->native_information = fmalloc(sizeof(FeriteFunctionNative)); ptr->native_information->code = fstrdup(function->native_information->code); ptr->native_information->file = fstrdup(function->native_information->file); - ptr->native_information->line = function->native_information->line; } else ptr->native_information = NULL; diff --git a/src/ferite_globals.c b/src/ferite_globals.c index 4207bf5..9f44536 100644 --- a/src/ferite_globals.c +++ b/src/ferite_globals.c @@ -58,6 +58,11 @@ int ferite_is_strict = 0; int ferite_show_partial_implementation = 0; +#ifdef FERITE_PROFILE +int ferite_enable_profiling = 0; +char *ferite_profile_filename_pattern = NULL; +#endif + /*! Generic function for memory management. Hides the actually memory manager */ void (*ferite_memory_init)(void); /*! Generic function for memory management. Hides the actually memory manager */ diff --git a/src/ferite_obj.c b/src/ferite_obj.c index 8aef4ab..c5dccfa 100644 --- a/src/ferite_obj.c +++ b/src/ferite_obj.c @@ -472,6 +472,12 @@ FeriteVariable *ferite_new_object( FeriteScript *script, FeriteClass *nclass, Fe FeriteVariable *ptr = NULL, *rval = NULL; FeriteFunction *func = NULL; FeriteVariable **params = NULL; +#ifdef FERITE_PROFILE + struct timespec begin_ts = {0, 0}; + struct timespec duration; + FeriteProfileFunction *callee = NULL; + FeriteProfileFunction *caller = NULL; +#endif FE_ENTER_FUNCTION; if(nclass != NULL) @@ -501,7 +507,15 @@ FeriteVariable *ferite_new_object( FeriteScript *script, FeriteClass *nclass, Fe func = ferite_find_constructor( script, VAO(ptr), params ); if( func != NULL ) { FUD(("OPS: Calling constructor in class %s\n", nclass->name )); - + +#ifdef FERITE_PROFILE + if (ferite_profile_enabled) { + /* Make a copy of the caller because func might reset it */ + caller = script->caller; + begin_ts = ferite_profile_function_begin(script, NULL, func, &callee); + } +#endif + if( func->type == FNC_IS_EXTRL ) { EXTERNAL_ENTER(func); rval = (func->fncPtr)( script, VAO(ptr), NULL, func, params ); @@ -509,6 +523,16 @@ FeriteVariable *ferite_new_object( FeriteScript *script, FeriteClass *nclass, Fe } else rval = ferite_script_function_execute( script, VAO(ptr), NULL, func, params ); + +#ifdef FERITE_PROFILE + if (ferite_profile_enabled) { + duration = ferite_profile_function_end(script, callee, script->current_op_line, &begin_ts); + if (caller != NULL) { + ferite_profile_add_caller(callee, caller, caller->calling_line, duration); + script->caller = NULL; + } + } +#endif if( rval == NULL || (rval != NULL && F_VAR_TYPE(rval) == F_VAR_OBJ && VAO(rval) == NULL) ) { @@ -539,4 +563,4 @@ FeriteVariable *ferite_new_object( FeriteScript *script, FeriteClass *nclass, Fe FE_LEAVE_FUNCTION( ptr ); } /*}}}*/ -/** @end */ \ No newline at end of file +/** @end */ diff --git a/src/ferite_profile.c b/src/ferite_profile.c new file mode 100644 index 0000000..6f0e4c6 --- /dev/null +++ b/src/ferite_profile.c @@ -0,0 +1,977 @@ +#ifdef FERITE_PROFILE +#ifdef HAVE_CONFIG_HEADER +#include "../config.h" +#endif +#include +#include "ferite.h" +#include "aphex.h" +#include +#include + +AphexMutex *ferite_profile_mutex = NULL; +#define INIT_PROFILE_LOCK() if (ferite_profile_mutex == NULL) \ + ferite_profile_mutex = aphex_mutex_recursive_create() +#define LOCK_PROFILE() aphex_mutex_lock(ferite_profile_mutex) +#define UNLOCK_PROFILE() aphex_mutex_unlock(ferite_profile_mutex) + +#define DIE(reason) do { fprintf(stderr, "%s:%d: %s\n", __FILE__, __LINE__, reason); exit(1); } while(0) +#define ONE_BILLION 1000000000L +#define ONE_MILLION 1000000L +#define TIMESPEC_TO_MILLISECONDS(ts) \ + (((long double)((ts).tv_sec) * ONE_BILLION + (ts).tv_nsec) / ONE_MILLION) +#define calculate_average_in_milliseconds(ts, freq) \ + (((long)((ts).tv_sec) * ONE_BILLION \ + + (ts).tv_nsec) / (long double)(freq) / ONE_MILLION) + +/* We don't expect many functions to be defined on the same line */ +#define FE_FUNCTIONS_HASH_SIZE 3 + +#define FE_CALLER_HASH_SIZE 256 +#define FERITE_PROFILE_NHASH 8192 +#define FERITE_PROFILE_STACK_SIZE 5 +static char *FILENAME_EVAL = "eval()"; +int ferite_profile_enabled = FE_FALSE; +static char profile_output[PATH_MAX] = { 0 }; +static FeriteProfileEntry *profile_entries[FERITE_PROFILE_NHASH] = { NULL }; +static struct timespec profile_start_ts = { 0, 0 }; +static int atexit_registered = 0; + +//#define FERITE_FAKE_CLOCK +#ifdef FERITE_FAKE_CLOCK +# define CLOCK_GETTIME(p) fake_clock_gettime(p) +static int fake_clock_gettime(struct timespec *ts) +{ + static int fake_clock_counter = 0; + ts->tv_sec = fake_clock_counter; + ts->tv_nsec = 0; + fake_clock_counter++; + return 0; +} +#else +# define CLOCK_TYPE CLOCK_THREAD_CPUTIME_ID +# define CLOCK_GETTIME(p) clock_gettime(CLOCK_TYPE, p) +#endif + +static size_t hash(const char *key, size_t limit) +{ + unsigned int hash = 0; + while (*key) { + hash = *key + 31 * hash; + key++; + } + return hash % limit; +} + +static int number_width(unsigned int num) +{ + unsigned int width = 0; + + do { + width += 1; + num /= 10; + } while (num > 0); + + return width; +} + +static int get_line_count(const char *filename, size_t *count) +{ + FILE *f = fopen(filename, "r"); + int ch; + int got_ch = 0; + int lines = 0; + + if (f == NULL) { + perror(filename); + return 1; + } + + while (EOF != (ch=fgetc(f))) { + got_ch = 1; + if (ch=='\n') + lines++; + } + if (lines == 0 && got_ch) { + /* File with no line terminators */ + lines = 1; + } + *count = lines; + + if (fclose(f) == EOF) { + perror(filename); + } + return 0; +} + +static int file_exists(const char *filename) +{ + struct stat st; + const int r = stat(filename, &st); + if (r == 0) + return 1; + if (errno == ENOENT) + return 0; + + fprintf(stderr, "Error stat'ing file %s\n", filename); + perror(filename); + return 0; +} + +static int profile_line_entry_init_for_eval(FeriteProfileEntry * const pe) +{ + pe->is_file = 0; + pe->lines = fcalloc_ngc(sizeof(FeriteProfileLineEntry), + 3 /* 1-based indexing + 1 line + 1 EOF line */ + ); + pe->line_count = 2; /* line 1 + EOF line */ + + return 0; +} + +static int profile_line_entry_init_for_file(FeriteProfileEntry * const pe) +{ + size_t line_count; + + if (get_line_count(pe->filename, &line_count) != 0) { + fprintf(stderr, "Error getting line count for %s", pe->filename); + return 1; + } + + pe->is_file = 1; + pe->lines = fcalloc_ngc(sizeof(FeriteProfileLineEntry), + line_count + + 1 /* 1-based indexing, for unused lines[0] */ + + 1 /* Count in EOF too */ + ); + pe->line_count = line_count + 1 /* EOF */; + + return 0; +} + +static int profile_line_entry_init_for_unknown(FeriteProfileEntry * const pe) +{ + size_t line_count = 1; + + pe->is_file = 0; + pe->lines = fcalloc_ngc(sizeof(FeriteProfileLineEntry), + line_count + + 1 /* 1-based indexing, for unused lines[0] */ + + 1 /* Count in EOF too */ + ); + pe->line_count = line_count + 1 /* EOF */; + + return 0; +} + +static int profile_line_entry_init(FeriteProfileEntry *pe) +{ + if (file_exists(pe->filename)) { + return profile_line_entry_init_for_file(pe); + } + + if (pe->filename == FILENAME_EVAL) { + return profile_line_entry_init_for_eval(pe); + } + + return profile_line_entry_init_for_unknown(pe); +} + +static FeriteProfileEntry *profile_init(const char *filename) +{ + FeriteProfileEntry *pe; + + pe = fmalloc_ngc(sizeof(FeriteProfileEntry)); + if (strncmp(filename, "eval()", 6) == 0) { + pe->filename = FILENAME_EVAL; + } else { + pe->filename = ferite_strdup((char *)filename, __FILE__, __LINE__); + } + if (profile_line_entry_init(pe)) { + return NULL; + } + + pe->next = NULL; + + return pe; +} + +static int is_profile_for(const char *filename, const FeriteProfileEntry *pe) +{ + return strcmp(pe->filename, filename) == 0; +} + +static FeriteProfileEntry *find_in_linked_list(const char *filename, FeriteProfileEntry *pe) +{ + while (pe) { + if (is_profile_for(filename, pe)) + return pe; + pe = pe->next; + } + return NULL; +} + +static FeriteProfileEntry *get_profile_entry_in_hash(const char *filename) +{ + unsigned int idx = hash(basename((char *)filename), FERITE_PROFILE_NHASH); + + return find_in_linked_list(filename, profile_entries[idx]); +} + +static FeriteProfileEntry *get_or_create_profile_entry_in_hash(const char *filename) +{ + FeriteProfileEntry *p = NULL; + unsigned int idx = hash(basename((char *)filename), FERITE_PROFILE_NHASH); + FeriteProfileEntry *pe = profile_entries[idx]; + + if (pe) { + p = find_in_linked_list(filename, pe); + if (p) + return p; + } + + p = profile_init(filename); + p->next = profile_entries[idx]; + profile_entries[idx] = p; + + return p; +} + +void ferite_profile_toggle(const int state) +{ + INIT_PROFILE_LOCK(); + +#ifdef FERITE_FAKE_CLOCK + fprintf(stderr, "Note: ferite profiling is using fake clock\n"); +#endif + + LOCK_PROFILE(); + + ferite_profile_enabled = state; + if (ferite_profile_enabled) { + if (profile_start_ts.tv_sec == 0 && profile_start_ts.tv_sec == 0) { +#ifdef FERITE_FAKE_CLOCK + CLOCK_GETTIME(&profile_start_ts); +#else + clock_gettime(CLOCK_REALTIME, &profile_start_ts); +#endif + } + } else { + profile_start_ts.tv_sec = 0; + profile_start_ts.tv_nsec = 0; + } + + UNLOCK_PROFILE(); +} + +static struct timespec timespec_diff(const struct timespec *old, struct timespec *new) +{ + struct timespec d; + if (new->tv_nsec < old->tv_nsec) { + new->tv_sec -= 1; + new->tv_nsec += ONE_BILLION; + } + d.tv_nsec = new->tv_nsec - old->tv_nsec; + d.tv_sec = new->tv_sec - old->tv_sec; + return d; +} + +static void timespec_add(struct timespec *t, const struct timespec delta) +{ + t->tv_nsec += delta.tv_nsec; + if (t->tv_nsec >= ONE_BILLION) { + t->tv_nsec %= ONE_BILLION; + t->tv_sec += 1; + } + t->tv_sec += delta.tv_sec; +} + +static void grow_pe_line_count(FeriteProfileEntry *pe, int line) +{ + size_t add = line - pe->line_count; + + pe->lines = frealloc_ngc(pe->lines, sizeof(FeriteProfileLineEntry) * (pe->line_count + add + 1)); + if (pe->lines == NULL) { + fprintf(stderr, "OOM reallocating profile lines record\n"); + UNLOCK_PROFILE(); + exit(1); + } + memset(pe->lines + pe->line_count + 1, 0, sizeof(FeriteProfileLineEntry) * add); + pe->line_count += add; +} + +static FeriteProfileLineEntry *get_line_entry(FeriteProfileEntry *pe, const size_t line) +{ + FeriteProfileLineEntry *le; + + if (!pe->is_file && line > pe->line_count ) + grow_pe_line_count(pe, line); + + + FE_ASSERT(line <= pe->line_count); + + le = &pe->lines[line]; + return le; +} + +static char *get_container_fqn(void *container, FeriteFunction *function) +{ + if (strncmp(function->name, "!__start__", 10) == 0) { + return "[main]"; + } + + if (strncmp(function->name, "!closure:", 9) == 0) { + fprintf(stderr, "FIXME: we shouldn't reach here"); + exit(1); + } + + if (function->klass != NULL) { + if (strncmp(function->klass->name, "!closure:", 9) == 0) { + return fstrdup(function->klass->name); + } + return ferite_generate_class_fqn(NULL, function->klass); + } + + if (container != NULL) { + FeriteNamespace *ns = (FeriteNamespace*) container; + if (ns->name != NULL && strncmp(ns->name, "!closure:", 9) == 0) { + fprintf(stderr, "FIXME: we shouldn't reach here"); + exit(1); + } + return ferite_generate_namespace_fqn(NULL, (FeriteNamespace*)container); + } + + return "[container unknown]"; +} + +static void get_filename_and_start_line(FeriteScript *script, FeriteFunction *f, char **filename, int *start_line) +{ + if (f->native_information != NULL) { + *filename = ferite_strdup(f->native_information->file, __FILE__, __LINE__); + *start_line = f->line; + } else if (f->bytecode != NULL) { + *filename = ferite_strdup(f->bytecode->filename, __FILE__, __LINE__); + *start_line = f->line; + } else { + // Both filename and bytecode are null - assume builtin obj methods + if (f->klass != NULL) { + int len = strlen(f->name); + *filename = ferite_generate_class_fqn(NULL, f->klass); + *filename = frealloc_ngc(*filename, len + 2 ); + strcat(*filename, "."); + strcat(*filename, f->name); + } else { + FE_ASSERT(0 /* We shouldn't reach here */); + } + *start_line = 1; + } + + if (strncmp(*filename, "eval()", 6) == 0 || strncmp(*filename, "entry:eval()", 12) == 0) { + ffree_ngc(*filename) + *filename = FILENAME_EVAL; + *start_line = f->bytecode->list[0]->line; + } +} + +FeriteProfileFunction *ferite_profile_get_function_profile(FeriteScript *script, void *container, FeriteFunction *function) +{ + FeriteProfileEntry *pe; + FeriteProfileLineEntry *le; + FeriteProfileFunction *fpf = NULL; + char *filename = NULL; + int start_line = -1; + + LOCK_PROFILE(); + + get_filename_and_start_line(script, function, &filename, &start_line); + + pe = get_or_create_profile_entry_in_hash(filename); + FE_ASSERT(pe != NULL); + + le = get_line_entry(pe, start_line); + + if (le->functions == NULL) { + le->functions = ferite_create_hash(NULL, FE_FUNCTIONS_HASH_SIZE); + } else { + fpf = ferite_hash_get(NULL, le->functions, function->name); + } + + if (fpf == NULL) { + fpf = fcalloc_ngc(sizeof(FeriteProfileFunction), 1); + fpf->filename = (char *)filename; + fpf->start_line = start_line; + fpf->is_native = function->native_information != NULL; + fpf->container = get_container_fqn(container, function); + fpf->name = fstrdup(function->name); + ferite_hash_add(NULL, le->functions, fpf->name, fpf); + } + + UNLOCK_PROFILE(); + + return fpf; +} + +void ferite_profile_set_caller(FeriteScript *script, void *container, FeriteFunction *function) +{ + FE_ASSERT(script->caller == NULL); + script->caller = ferite_profile_get_function_profile(script, container, function); + script->caller->calling_line = script->current_op_line; +} + +struct timespec ferite_profile_function_begin(FeriteScript *script, void *container, FeriteFunction *function, FeriteProfileFunction **fpf) +{ + struct timespec begin_ts; + + CLOCK_GETTIME(&begin_ts); + + LOCK_PROFILE(); + + *fpf = ferite_profile_get_function_profile(script, container, function); + (*fpf)->ncalls++; + + UNLOCK_PROFILE(); + + return begin_ts; +} + +struct timespec ferite_profile_function_end(FeriteScript *script, FeriteProfileFunction *fpf, int end_line, struct timespec *begin_ts) +{ + struct timespec end_ts, duration; + + CLOCK_GETTIME(&end_ts); + + LOCK_PROFILE(); + + // TODO handle two functions defined on the same line + if (fpf->end_line < end_line) { + fpf->end_line = end_line; + } + + duration = timespec_diff(begin_ts, &end_ts); + timespec_add(&fpf->inclusive_duration, duration); + + UNLOCK_PROFILE(); + + return duration; +} + +struct timespec ferite_profile_line_begin(FeriteScript *script, const char *filename, const size_t line) +{ + FeriteProfileEntry *pe; + FeriteProfileLineEntry *le; + struct timespec begin_ts = {0,0}; + + CLOCK_GETTIME(&begin_ts); + + LOCK_PROFILE(); + + pe = get_or_create_profile_entry_in_hash(filename); + if (pe == NULL) { + fprintf(stderr, + "Error creating profile entry for file %s\n", filename); + UNLOCK_PROFILE(); + return begin_ts; + } + + le = get_line_entry(pe, line); + if (le == NULL) { + UNLOCK_PROFILE(); + return begin_ts; + } + + le->ncalls++; + + UNLOCK_PROFILE(); + + return begin_ts; +} + +void ferite_profile_line_end(FeriteScript *script, const char *filename, const size_t line, struct timespec *begin_ts) +{ + FeriteProfileEntry *pe; + FeriteProfileLineEntry *le; + struct timespec end_ts, duration; + + // TODO either get rid of these getpid()s or use them at least once + // to verify locking works as intended + static pid_t pid = 0; + if (pid == 0) { + pid = getpid(); + } + pid_t other_pid = getpid(); + if (pid != other_pid) { + fprintf(stderr, "pid %d, other pid = %d\n", pid, other_pid); + } + + CLOCK_GETTIME(&end_ts); + + LOCK_PROFILE(); + + pe = get_profile_entry_in_hash(filename); + if (pe == NULL) { + fprintf(stderr, "FIXME No hash for file %s ???\n", filename); + UNLOCK_PROFILE(); + return; + } + if (pe->line_count < line) { + if (pe->is_file) { + fprintf(stderr, + "Error: Line number %lu exceeds the one we " + "counted initially (%lu) for file %s", + line, pe->line_count, filename); + UNLOCK_PROFILE(); + exit(1); + } else { + grow_pe_line_count(pe, line); + } + } + + le = &pe->lines[line]; + + duration = timespec_diff(begin_ts, &end_ts); + timespec_add(&le->total_duration, duration); + + UNLOCK_PROFILE(); +} + +static void get_caller_key(FeriteProfileFunction *caller, int caller_line, FeriteProfileFunction *callee, char *buf, size_t size) +{ + int nprinted; + + nprinted = snprintf(buf, size, "%s:%d:%s:%d,%s:%d:%s", + caller->filename, caller->start_line, caller->name, + caller_line, + callee->filename, callee->start_line, callee->name); + if (nprinted >= size) { + fprintf(stderr, "FIXME: ferite profile: get_caller_key(): failed " + "assumption: bufsize %lu is to small\n", size); + exit(1); + } +} + +void ferite_profile_add_caller(FeriteProfileFunction *callee, FeriteProfileFunction *caller, int caller_line, struct timespec duration_ts) +{ + FeriteProfileFunctionCaller *fpfc; + char caller_key[PATH_MAX*3]; + + LOCK_PROFILE(); + + if (callee->callers == NULL) { + callee->callers = ferite_create_hash(NULL, FE_CALLER_HASH_SIZE); + } + + get_caller_key(caller, caller_line, callee, caller_key, PATH_MAX*2); + fpfc = ferite_hash_get(NULL, callee->callers, caller_key); + if (fpfc == NULL) { + fpfc = fcalloc_ngc(sizeof(FeriteProfileFunctionCaller), 1); + fpfc->caller = caller; + fpfc->caller_line = caller_line; + ferite_hash_add(NULL, callee->callers, caller_key, fpfc); + } + + fpfc->frequency += 1; + timespec_add(&fpfc->total_duration, duration_ts); + timespec_add(&caller->exclusive_duration, duration_ts); + + UNLOCK_PROFILE(); +} + +static int maybe_expand_pid(char *buf, size_t size) +{ + char *p = buf; + char len = strlen(buf); + pid_t pid = getpid(); + + while (*p && p-buf < size) { + if (*p == '%' && *(p+1) == '%') { + p++; + } else if (*p == '%' && *(p+1) == 'i') { + size_t w = number_width(pid); + + if (w > 2) { + int add = w - 2; /*%p*/ + if (len + add < PATH_MAX) { + char *j; + char save = *(p+2); + /* Shift chars to the right to make + * space for the pid */ + for (j = buf+len; j > p+1; j--) { + *(j+add) = *j; + *j = 'x'; + } + snprintf(p, (buf+len+w)-p, "%d", pid); + *(p+w) = save; + len += add; + } else { + printf("Not enough buffer space to include process id\n"); + return 0; + } + } else if (w < 2) { + char *j; + /* It must be 1 */ + FE_ASSERT(w == 1); + *p = pid + '0'; + /* Shift chars left by 1 */ + for (j = p + 1; j <= buf + len; j++) { + *j = *(j+1); + } + len--; + } else { /* w == 2 */ + char save = *(p+2); + snprintf(p, (buf+len+1)-p, "%d", pid); + *(p+2) = save; + } + } + p++; + } + return len; +} + + +static int format_profile_filename(char *format, char *buf) +{ + struct tm now; + time_t t; + char fmt[PATH_MAX]; + + strncpy(fmt, format, PATH_MAX); + (void)maybe_expand_pid(fmt, PATH_MAX); + + (void)time(&t); + (void)localtime_r(&t, &now); + + if (strftime(buf, PATH_MAX, fmt, &now) == 0) { + fprintf(stderr, "Error: profile output pattern '%s' results in " + "empty filename\n", profile_output); + return 0; + } + + return 1; +} + +static void json_comma(FILE *f) +{ + fprintf(f, ","); +} + +static void json_key(FILE *f, char *key) +{ + fprintf(f, "\"%s\":", key); +} + +static void json_array_open(FILE *f, char *key) +{ + if (key != NULL) + json_key(f, key); + fprintf(f, "["); +} + +static void json_array_close(FILE *f) +{ + fprintf(f, "]"); +} + +static void json_dict_open(FILE *f, char *key) +{ + if (key != NULL) + json_key(f, key); + fprintf(f, "{"); +} + +static void json_dict_close(FILE *f) +{ + fprintf(f, "}"); +} + +static void json_string(FILE *f, char *key, char *value) +{ + fprintf(f, "\"%s\":\"%s\"", key, value); +} + +static void json_positive_number(FILE *f, char *key, size_t value) +{ + fprintf(f, "\"%s\":%lu", key, value); +} + +static void json_bool(FILE *f, char *key, int value) +{ + fprintf(f, "\"%s\":%s", key, value ? "true":"false"); +} + +static void json_null(FILE *f, char *key) +{ + if (key) { + fprintf(f, "\"%s\":", key); + } + fprintf(f, "null"); +} + +static void json_timespec(FILE *f, char *key, struct timespec value) +{ + json_dict_open(f, key); + json_positive_number(f, "sec", value.tv_sec); + json_comma(f); + json_positive_number(f, "nsec", value.tv_nsec); + json_dict_close(f); +} + +static void write_json_name_and_namespace(FILE *f, FeriteProfileFunction *function) +{ + json_string(f, "name", function->name); + json_comma(f); + if (function->container != NULL) { + json_string(f, "namespace", function->container); + } else { + json_null(f, "namespace"); + } +} + +static void write_json_one_function_caller(FILE *f, FeriteProfileFunctionCaller *fpfc) +{ + char *realname; + FeriteProfileFunction *caller = fpfc->caller; + + json_dict_open(f, NULL); + write_json_name_and_namespace(f, caller); + json_comma(f); + if (file_exists(caller->filename)) { + realname = realpath(caller->filename, NULL); + json_string(f, "file", realname); + free(realname); + } else { + json_string(f, "file", caller->filename); + } + json_comma(f); json_positive_number(f, "at", fpfc->caller_line); + json_comma(f); json_positive_number(f, "frequency", fpfc->frequency); + json_comma(f); json_timespec(f, "total_duration", fpfc->total_duration); + json_dict_close(f); +} + +static void write_json_callers(FILE *f, FeriteHash *callersHash) +{ + FeriteHashBucket *fhb; + FeriteIterator iter; + iter.curbucket = NULL; + iter.curindex = 0; + int has_previous_entry = 0; + + if (callersHash == NULL) { + json_null(f, "callers"); + return; + } + + json_array_open(f, "callers"); + while ((fhb = ferite_hash_walk(NULL, callersHash, &iter)) != NULL) { + FeriteProfileFunctionCaller *fpfc = fhb->data; + if (has_previous_entry) { + json_comma(f); + } + write_json_one_function_caller(f, fpfc); + has_previous_entry = 1; + } + json_array_close(f); +} + +#define ZERO_TIME(ts) ((ts)->tv_sec == 0 && (ts)->tv_nsec == 0) +static void write_json_one_function_callee(FILE *f, FeriteProfileFunction *callee) { + struct timespec *inclusive; + + json_dict_open(f, NULL); + json_string(f, "name", callee->name); + json_comma(f); json_positive_number(f, "start_line", callee->start_line); + json_comma(f); + if (callee->container != NULL) { + json_string(f, "namespace", callee->container); + } else { + json_null(f, "namespace"); + } + json_comma(f); json_positive_number(f, "hits", callee->ncalls); + json_comma(f); json_bool(f, "is_native", callee->is_native); + + inclusive = &callee->inclusive_duration; + if (ZERO_TIME(inclusive) && !ZERO_TIME(&callee->exclusive_duration)) { + /* We have eclusive duration but zero inclusive duration. This + * may happen if this function is called from a native function + * so we have no record of the total time it spent doing its + * stuff (inclusive time). We know that it calls some other + * function because its exclusive_duration is not zero. So set + * its inclusive_duration to be equal to its exclusive_duration + */ + inclusive = &callee->exclusive_duration; + } + + json_comma(f); json_timespec(f, "inclusive_duration", *inclusive); + json_comma(f); json_timespec(f, "exclusive_duration", callee->exclusive_duration); + json_comma(f); + + write_json_callers(f, callee->callers); + + json_dict_close(f); +} + +static void write_json_functions(FILE *f, FeriteHash *hash) +{ + FeriteHashBucket *fhb; + int has_previous_entry = 0; + FeriteIterator iter; + iter.curbucket = NULL; + iter.curindex = 0; + + if (hash == NULL) { + json_null(f, "functions"); + return; + } + + json_array_open(f, "functions"); + while ((fhb = ferite_hash_walk(NULL, hash, &iter)) != NULL) { + FeriteProfileFunction *callee = fhb->data; + if (has_previous_entry) { + json_comma(f); + } + write_json_one_function_callee(f, callee); + has_previous_entry = 1; + } + + json_array_close(f); +} + +static void write_line_profile(FILE *f, FeriteProfileLineEntry *le) +{ + if (le->ncalls == 0 && le->functions == NULL) { + json_null(f, NULL); + return; + + } + + json_dict_open(f, NULL); + json_positive_number(f, "hits", le->ncalls); + json_comma(f); json_timespec(f, "total_duration", le->total_duration); + json_comma(f); + + write_json_functions(f, le->functions); + json_dict_close(f); +} + +static void write_json_profile_line_entries_for_one_file(FILE *f, FeriteProfileEntry *pe) +{ + FeriteProfileLineEntry *le; + char path[PATH_MAX]; + size_t line_no; + char *filename = pe->filename; + #define LINE_METRIC_SZ 128 + int has_previous_entry = 0; + + if (realpath(pe->filename, path) != NULL) + filename = path; + else { + if (ENOENT != errno) { + perror(pe->filename); + + } + } + + json_array_open(f, filename); + + for (line_no = 1; line_no <= pe->line_count; line_no++) { + le = &pe->lines[line_no]; + if (has_previous_entry) { + json_comma(f); + } + write_line_profile(f, le); + has_previous_entry = 1; + } + + json_array_close(f); +} + +static void save_json_profile() +{ + int i; + FILE *f; + char filename[PATH_MAX]; + int has_previous_entry = 0; + struct timespec total_duration; + struct timespec profile_end_ts; + + LOCK_PROFILE(); + +#ifdef FERITE_FAKE_CLOCK + CLOCK_GETTIME(&profile_end_ts); +#else + clock_gettime(CLOCK_REALTIME, &profile_end_ts); +#endif + total_duration = timespec_diff(&profile_start_ts, &profile_end_ts); + + if (format_profile_filename(profile_output, filename) == 0) { + UNLOCK_PROFILE(); + return; + } + + f = fopen(filename, "w"); + if (f == NULL) { + perror(filename); + UNLOCK_PROFILE(); + return; + } + + json_dict_open(f, NULL); + json_timespec(f, "start", profile_start_ts); + json_comma(f); json_timespec(f, "stop", profile_end_ts); + json_comma(f); json_timespec(f, "duration", total_duration); + json_comma(f); json_dict_open(f, "files"); + + for (i = 0; i < FERITE_PROFILE_NHASH; i++) { + FeriteProfileEntry *pe = profile_entries[i]; + while (pe) { + if (has_previous_entry) { + json_comma(f); + } + write_json_profile_line_entries_for_one_file(f, pe); + has_previous_entry = 1; + pe = pe->next; + } + } + + json_dict_close(f); + json_dict_close(f); + + UNLOCK_PROFILE(); + + if (fclose(f) == EOF) + perror(filename); + +} + +void save_profile(void) { + save_json_profile(); +} + +void ferite_profile_set_save_at_exit() +{ + if (! atexit_registered) { + atexit_registered = 1; + atexit(save_profile); + } +} + +void ferite_profile_save() +{ + if (atexit_registered) { + fprintf(stderr, "Warning: save atexit was set but ferite_profile_save() is called.\n"); + } + save_json_profile(); +} + +void ferite_profile_set_filename_format(const char *filename) +{ + LOCK_PROFILE(); + + if (strncmp(profile_output, filename, PATH_MAX) == 0) { + UNLOCK_PROFILE(); + return; + } + strncpy(profile_output, filename, PATH_MAX); + profile_output[PATH_MAX-1] = '\0'; + + UNLOCK_PROFILE(); +} +#endif diff --git a/src/ferite_script.c b/src/ferite_script.c index 36ed0ab..67b3c70 100644 --- a/src/ferite_script.c +++ b/src/ferite_script.c @@ -53,6 +53,9 @@ FeriteScript *ferite_new_script() FE_ENTER_FUNCTION; ptr = fmalloc_ngc( sizeof( FeriteScript ) ); +#ifdef FERITE_PROFILE + ptr->caller = NULL; +#endif ptr->filename = NULL; ptr->scripttext = NULL; @@ -61,7 +64,7 @@ FeriteScript *ferite_new_script() ptr->include_list = ferite_create_stack( NULL, FE_COMPILER_INTERNAL_STACK_SIZE ); ptr->current_op_file = NULL; - ptr->current_op_line = 0; + ptr->current_op_line = 1; ptr->error_state = 0; ptr->keep_execution = 0; diff --git a/test/Makefile.am b/test/Makefile.am index cfa0c35..9980683 100644 --- a/test/Makefile.am +++ b/test/Makefile.am @@ -16,6 +16,6 @@ INCLUDES = -I. -I$(top_srcdir) -I$(top_srcdir)/src -I.. \ -I$(top_srcdir)/libs/aphex/include -I$(top_srcdir)/include \ -I$(includedir) -I$(prefix)/include -DEFS=@thread_defs@ @gc_defs@ +DEFS=@thread_defs@ @gc_defs@ @profile_defs@ LDADD = $(top_builddir)/src/libferite.la -L$(libdir) -L$(prefix)/lib @gc_libs@ diff --git a/test/main.c b/test/main.c index 3f397a9..6f1ec20 100644 --- a/test/main.c +++ b/test/main.c @@ -118,6 +118,13 @@ void print_version() printf( "%s %s [built: %s %s] [%s]\n", PACKAGE, VERSION, __DATE__, __TIME__, PLATFORM ); printf( " Base Cross Platform Library Path: %s\n", XPLAT_LIBRARY_DIR ); printf( " Base Native Library Path: %s\n", NATIVE_LIBRARY_DIR ); + printf( " Profiling: %s\n", +#ifdef FERITE_PROFILE + "enabled" +#else + "disabled" +#endif + ); } void print_copyright() @@ -515,6 +522,12 @@ int main( int argc, char **argv ) /* delete the script */ ferite_script_delete( script ); +#ifdef FERITE_PROFILE + if (ferite_profile_enabled) { + ferite_profile_save(); + } +#endif + /* deinitialise the engien */ ferite_deinit(); aphex_free( opt.scriptname );