Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

profile: new column for time of the function without the time of its children functions #24056

Merged
merged 1 commit into from
Mar 27, 2025
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions vlib/v/gen/c/cgen.v
Original file line number Diff line number Diff line change
Expand Up @@ -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())
Expand Down
14 changes: 9 additions & 5 deletions vlib/v/gen/c/profile.v
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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()
Expand All @@ -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);')
}
Expand Down
Loading