cgen: add a -profile report column, to show only the func time, *excluding* the accumulated children calls time (usable through ./v -profile - run a.v |sort -nk3 for example) (#24056)

This commit is contained in:
Eliyaan (Nopana) 2025-03-27 13:03:39 +01:00 committed by GitHub
parent c22a9eb57e
commit a03d62e41f
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
2 changed files with 10 additions and 5 deletions

View File

@ -574,6 +574,7 @@ pub fn gen(files []&ast.File, mut table ast.Table, pref_ &pref.Preferences) GenO
b.write_string2('\n // V preincludes:\n', g.preincludes.str())
b.write_string2('\n// V cheaders:\n', g.cheaders.str())
if g.pcs_declarations.len > 0 {
g.pcs_declarations.writeln('double prof_measured_time = 0.0;') // does not work for multithreaded
b.write_string2('\n// V profile counters:\n', g.pcs_declarations.str())
}
b.write_string2('\n// V includes:\n', g.includes.str())

View File

@ -32,13 +32,17 @@ fn (mut g Gen) profile_fn(fn_decl ast.FnDecl) {
g.writeln('\tv__profile_enabled = true;')
}
g.writeln('\tdouble _PROF_FN_START = ${measure_fn_name}();')
g.writeln('\tdouble _PROF_PREV_MEASURED_TIME = prof_measured_time;')
g.writeln('\tif(v__profile_enabled) { ${fn_profile_counter_name_calls}++; } // ${fn_name}')
g.writeln('')
g.defer_profile_code = '\tif(v__profile_enabled) { ${fn_profile_counter_name} += ${measure_fn_name}() - _PROF_FN_START; }'
g.defer_profile_code = '\tif(v__profile_enabled) { double _PROF_ELAPSED = ${measure_fn_name}() - _PROF_FN_START; '
g.defer_profile_code += '${fn_profile_counter_name} += _PROF_ELAPSED; '
g.defer_profile_code += '${fn_profile_counter_name}_only_current += _PROF_ELAPSED - (prof_measured_time - _PROF_PREV_MEASURED_TIME); '
g.defer_profile_code += 'prof_measured_time = _PROF_PREV_MEASURED_TIME + _PROF_ELAPSED; }'
if should_restore_v__profile_enabled {
g.defer_profile_code += '\n\t\tv__profile_enabled = _prev_v__profile_enabled;'
}
g.pcs_declarations.writeln('double ${fn_profile_counter_name} = 0.0; u64 ${fn_profile_counter_name_calls} = 0;')
g.pcs_declarations.writeln('double ${fn_profile_counter_name} = 0.0; double ${fn_profile_counter_name}_only_current = 0.0; u64 ${fn_profile_counter_name_calls} = 0;')
g.pcs << ProfileCounterMeta{
fn_name: cfn_name
vpc_name: fn_profile_counter_name
@ -49,7 +53,7 @@ fn (mut g Gen) profile_fn(fn_decl ast.FnDecl) {
pub fn (mut g Gen) gen_vprint_profile_stats() {
g.pcs_declarations.writeln('void vprint_profile_stats(){')
fstring := '"%14llu %14.3fms %14.0fns %s \\n"'
fstring := '"%14llu %14.3fms %14.3fms %14.0fns %s \\n"'
g.pcs_declarations.writeln('\tf64 f = 1.0;')
if g.pref.os == .windows {
// QueryPerformanceCounter() / QueryPerformanceFrequency()
@ -60,13 +64,13 @@ pub fn (mut g Gen) gen_vprint_profile_stats() {
}
if g.pref.profile_file == '-' {
for pc_meta in g.pcs {
g.pcs_declarations.writeln('\tif (${pc_meta.vpc_calls}) printf(${fstring}, ${pc_meta.vpc_calls}, (${pc_meta.vpc_name}*f)/1000000.0, (${pc_meta.vpc_name}*f)/${pc_meta.vpc_calls}, "${pc_meta.fn_name}" );')
g.pcs_declarations.writeln('\tif (${pc_meta.vpc_calls}) printf(${fstring}, ${pc_meta.vpc_calls}, (${pc_meta.vpc_name}*f)/1000000.0, (${pc_meta.vpc_name}_only_current*f)/1000000.0, (${pc_meta.vpc_name}*f)/${pc_meta.vpc_calls}, "${pc_meta.fn_name}" );')
}
} else {
g.pcs_declarations.writeln('\tFILE * fp;')
g.pcs_declarations.writeln('\tfp = fopen ("${g.pref.profile_file}", "w+");')
for pc_meta in g.pcs {
g.pcs_declarations.writeln('\tif (${pc_meta.vpc_calls}) fprintf(fp, ${fstring}, ${pc_meta.vpc_calls}, (${pc_meta.vpc_name}*f)/1000000.0, (${pc_meta.vpc_name}*f)/${pc_meta.vpc_calls}, "${pc_meta.fn_name}" );')
g.pcs_declarations.writeln('\tif (${pc_meta.vpc_calls}) fprintf(fp, ${fstring}, ${pc_meta.vpc_calls}, (${pc_meta.vpc_name}*f)/1000000.0, (${pc_meta.vpc_name}_only_current*f)/1000000.0, (${pc_meta.vpc_name}*f)/${pc_meta.vpc_calls}, "${pc_meta.fn_name}" );')
}
g.pcs_declarations.writeln('\tfclose(fp);')
}