core-debug.sh (23647B)
1 # -*- mode: sh; mode: sh-bash -*- 2 3 ## @fn ble/debug/setdbg 4 function ble/debug/setdbg { 5 ble/bin/rm -f "$_ble_base_run/dbgerr" 6 local ret 7 ble/util/readlink /proc/self/fd/3 3>&1 8 ln -s "$ret" "$_ble_base_run/dbgerr" 9 } 10 ## @fn ble/debug/print text 11 function ble/debug/print { 12 if [[ -e $_ble_base_run/dbgerr ]]; then 13 ble/util/print "$1" >> "$_ble_base_run/dbgerr" 14 else 15 ble/util/print "$1" >&2 16 fi 17 } 18 ## @fn ble/debug/leakvar#check 19 ## [デバグ用] 宣言忘れに依るグローバル変数の汚染位置を特定するための関数。 20 ## 21 ## 使い方 22 ## 23 ## ``` 24 ## eval "${_ble_debug_check_leak_variable//@var/ret}" 25 ## ...codes1... 26 ## ble/debug/leakvar#check ret tag1 27 ## ...codes2... 28 ## ble/debug/leakvar#check ret tag2 29 ## ...codes3... 30 ## ble/debug/leakvar#check ret tag3 31 ## ``` 32 _ble_debug_check_leak_variable='local @var=__t1wJltaP9nmow__' 33 function ble/debug/leakvar#reset { 34 builtin eval "$1=__t1wJltaP9nmow__" 35 } 36 function ble/debug/leakvar#check { 37 local ext=$? 38 if [[ ${!1} != __t1wJltaP9nmow__ ]] && ble/variable#is-global "$1"; then 39 local IFS=$_ble_term_IFS 40 ble/util/print "$1=${!1}:${*:2} [${FUNCNAME[*]:1:5}]" >> ~/a.txt # DEBUG_LEAKVAR 41 builtin eval "$1=__t1wJltaP9nmow__" 42 fi 43 return "$?" 44 } 45 function ble/debug/leakvar#list { 46 local _ble_local_exclude_file=${_ble_base_repository:-$_ble_base}/make/debug.leakvar.exclude-list.txt 47 if [[ ! -f $_ble_local_exclude_file ]]; then 48 ble/util/print "$_ble_local_exclude_file: not found." >&2 49 return 1 50 fi 51 set | ble/bin/grep -Eavf "$_ble_local_exclude_file" | ble/bin/grep -Eao '^[[:alnum:]_]+=' 52 return 0 53 } 54 55 function ble/debug/print-variables/.append { 56 local q=\' Q="'\''" 57 _ble_local_out=$_ble_local_out"$1='${2//$q/$Q}'" 58 } 59 function ble/debug/print-variables/.append-array { 60 local ret; ble/string#quote-words "${@:2}" 61 _ble_local_out=$_ble_local_out"$1=($ret)" 62 } 63 function ble/debug/print-variables { 64 (($#)) || return 0 65 66 local flags= tag= arg 67 local -a _ble_local_vars=() 68 while (($#)); do 69 arg=$1; shift 70 case $arg in 71 (-t) tag=$1; shift ;; 72 (-*) ble/util/print "print-variables: unknown option '$arg'" >&2 73 flags=${flags}e ;; 74 (*) ble/array#push _ble_local_vars "$arg" ;; 75 esac 76 done 77 [[ $flags == *e* ]] && return 1 78 79 local _ble_local_out= _ble_local_var= 80 [[ $tag ]] && _ble_local_out="$tag: " 81 ble/util/unlocal flags tag arg 82 for _ble_local_var in "${_ble_local_vars[@]}"; do 83 if ble/is-array "$_ble_local_var"; then 84 builtin eval -- "ble/debug/print-variables/.append-array \"\$_ble_local_var\" \"\${$_ble_local_var[@]}\"" 85 else 86 ble/debug/print-variables/.append "$_ble_local_var" "${!_ble_local_var}" 87 fi 88 _ble_local_out=$_ble_local_out' ' 89 done 90 ble/debug/print "${_ble_local_out%' '}" 91 } 92 93 _ble_debug_stopwatch=() 94 function ble/debug/stopwatch/start { 95 ble/array#push _ble_debug_stopwatch "${EPOCHREALTIME:-$SECONDS.000000}" 96 } 97 function ble/debug/stopwatch/stop { 98 local end=${EPOCHREALTIME:-$SECONDS.000000} 99 if local ret; ble/array#pop _ble_debug_stopwatch; then 100 local usec=$(((${end%%[.,]*}-${ret%%[,.]*})*1000000+(10#0${end#*[.,]}-10#0${ret#*[,.]}))) 101 printf '[%3d.%06d sec] %s\n' "$((usec/1000000))" "$((usec%1000000))" "$1" 102 else 103 printf '[---.------ sec] %s\n' "$1" 104 fi 105 } 106 107 _ble_debug_profiler_magic=__GdWfuwABAUmlg__ 108 _ble_debug_profiler_prefix= 109 _ble_debug_profiler_original_xtrace= 110 _ble_debug_profiler_original_xtrace_ps4= 111 function ble/debug/profiler/start { 112 [[ ! $_ble_debug_profiler_prefix ]] || return 1 113 if ((_ble_bash<50000)); then 114 ble/util/print "ble.sh: profiler is only supported in Bash 5.0+." >&2 115 return 2 116 fi 117 118 local prefix=${1:-prof.$$} 119 [[ $prefix == /* ]] || prefix=$PWD/$prefix 120 _ble_debug_profiler_prefix=$prefix 121 122 _ble_debug_profiler_original_xtrace=$bleopt_debug_xtrace 123 _ble_debug_profiler_original_xtrace_ps4=$bleopt_debug_xtrace_ps4 124 bleopt debug_xtrace="$prefix.xtrace" 125 bleopt debug_xtrace_ps4='+${#BASH_LINENO[@]} ${BASHPID:-$$} ${EPOCHREALTIME:-SECONDS} ${FUNCNAME:-(global)} ${LINENO:--} ${BASH_SOURCE:--} '"$_ble_debug_profiler_magic"' ' 126 127 blehook EXIT!=ble/debug/profiler/stop 128 } 129 130 function ble/debug/profiler/stop { 131 [[ $_ble_debug_profiler_prefix ]] || return 1 132 local prefix=$_ble_debug_profiler_prefix 133 _ble_debug_profiler_prefix= 134 bleopt debug_xtrace="$_ble_debug_profiler_original_xtrace" 135 bleopt debug_xtrace_ps4="$_ble_debug_profiler_original_xtrace_ps4" 136 137 local f1=$prefix.xtrace 138 local f2=$prefix.line.txt 139 local f3=$prefix.line.html 140 local f4=$prefix.func.txt 141 142 # count lines 143 local nline 144 ble/util/print "ble/debug/profiler: counting lines..." 145 ble/util/assign-words nline 'ble/bin/wc -l "$f1" 2>/dev/null' 146 ble/util/print $'\e[A\rble/debug/profiler: counting lines... '"$nline" 147 148 # awk 149 local -a awk_args=() 150 [[ -s $f2 ]] && ble/array#push awk_args mode=line_stat "$f2" 151 [[ -s $f4 ]] && ble/array#push awk_args mode=func_stat "$f4" 152 ble/array#push awk_args mode=xtrace "$f1" 153 local -x file_func=$f4.part 154 local -x file_line=$f2.part 155 local -x file_line_html= #$f3 # currently .html output is disabled 156 ble/bin/awk -v magic="$_ble_debug_profiler_magic" -v nline="$nline" ' 157 BEGIN { 158 file_func = ENVIRON["file_func"]; 159 file_line = ENVIRON["file_line"]; 160 file_line_html = ENVIRON["file_line_html"]; 161 162 xtrace_debug_enabled = 1; 163 print "ble/debug/profiler: collecting information..." >"/dev/stderr"; 164 if (nline) progress_interval = int(nline / 100); 165 166 ipid = 0; 167 ilabel = 0; 168 ifname = 0; 169 _usec_sec0 = ""; 170 } 171 172 function to_percentage(value) { 173 value *= 100; 174 if (value >= 100) return sprintf("%d%%", int(value)); 175 if (value >= 10) return sprintf("%.2f%%", value); 176 if (value >= 0.1) return sprintf("%.3f%%", value); 177 if (value >= 0.0001) return sprintf(".%04d%%", int(value * 10000)); 178 return "0.0%"; 179 } 180 181 function pids_register(pid) { 182 if (pid_mark[pid] == "") { 183 pid_mark[pid] = ipid; 184 pids[ipid++] = pid; 185 } 186 } 187 188 function pids_clear() { 189 ipid = 0; 190 delete pids; 191 delete pid_mark; 192 } 193 194 function parse_usec(text, _, sec, usec) { 195 sec = text; 196 usec = 0; 197 if (sub(/[.,].*/, "", sec)) { 198 usec = text 199 sub(/^.*[.,]0*/, "", usec); 200 } 201 202 if (_usec_sec0 == "") 203 _usec_sec0 = sec; 204 sec -= _usec_sec0; 205 return sec * 1000000 + usec; 206 } 207 208 ## @var[out] level depth pid usec fname label command 209 function parse_line(_, s) { 210 s = $1; 211 level = gsub(/\+/, "", s); 212 depth = 1 + (s > 0 ? s : 0); 213 level += depth - 1; 214 pid = $2; 215 usec = parse_usec($3); 216 217 fname = $4; 218 lineno = $5; 219 source = $6; 220 for (i = 7; $i != magic && i <= NF; i++) 221 source = source " " $i; 222 label = sprintf("\x1b[35m%s\x1b[36m (%s:\x1b[32m%s\x1b[36m):\x1b[m", source, fname, lineno); 223 command = ""; 224 if ($i == magic) { 225 command = $(++i); 226 for (i++; i <= NF; i++) 227 command = command " " $i; 228 } 229 } 230 231 #-------------------------------------------------------------------------- 232 # line_stat 233 234 function lines_level_push(pid, level, usec, label, command, _, lv) { 235 if (!line_stat[label, "count"]++) 236 labels[ilabel++] = label; 237 238 lines_level_pop(pid, level, usec); 239 240 # debug 241 #for (lv = ilevel[pid] + 1; lv < level; lv++) 242 # if (stk[pid, lv, "label"] != "") 243 # print "unexpected label[" lv "] = (" stk[pid, lv, "label"] ") ilevel=" ilevel[pid] "->" level >"/dev/stderr"; 244 245 stk[pid, level, "label"] = label; 246 stk[pid, level, "begin"] = usec; 247 stk[pid, level, "child"] = 0.0; 248 stk[pid, level, "allstep_count"] = 0; 249 stk[pid, level, "substep_count"] = 0; 250 stk[pid, level, "substep_time"] = 0.0; 251 stk[pid, level, "command"] = command; 252 ilevel[pid] = level; 253 } 254 255 function lines_level_getParent(pid, lv) { 256 for (lv--; lv >= 1; lv--) 257 if (stk[pid, lv, "label"] != "") break; 258 return lv; 259 } 260 261 function lines_level_pop(pid, level, usec, _, lv, label, elapsed, plv) { 262 for (lv = ilevel[pid]; lv >= level; lv--) { 263 label = stk[pid, lv, "label"]; 264 stk[pid, lv, "label"] = ""; 265 if (label == "") continue; 266 267 elapsed = usec - stk[pid, lv, "begin"]; 268 if (elapsed < 0) { 269 #print "[debug] negative time: " NR ": " $0 >"/dev/stderr"; 270 elapsed = 0.0; 271 } 272 273 line_stat[label, "total"] += elapsed; 274 line_stat[label, "child"] += stk[pid, lv, "child"]; 275 if (lv >= 3) 276 stk[pid, lv - 2, "child"] += elapsed; 277 278 line_stat[label, "allstep_count"] += stk[pid, lv, "allstep_count"]; 279 line_stat[label, "substep_count"] += stk[pid, lv, "substep_count"]; 280 line_stat[label, "substep_time"] += stk[pid, lv, "substep_time"]; 281 if ((plv = lines_level_getParent(pid, lv))) { 282 stk[pid, plv, "allstep_count"] += 1 + stk[pid, lv, "allstep_count"]; 283 stk[pid, plv, "substep_count"]++; 284 stk[pid, plv, "substep_time"] += elapsed; 285 } 286 287 max_time = line_stat[label, "max_time"]; 288 if (max_time == "" || elapsed > max_time) { 289 line_stat[label, "max_command"] = stk[pid, lv, "command"]; 290 line_stat[label, "max_time"] = elapsed; 291 line_stat[label, "max_child"] = stk[pid, lv, "child"]; 292 } 293 } 294 ilevel[pid] = lv; 295 } 296 297 function lines_text_header(_, line) { 298 line = sprintf("# %6s %8s %8s", "count", "subcount", "allcount"); 299 line = line sprintf(" %10s %-6s %10s %-6s %10s", "total_msec", "TOTAL%", "self_msec", "SELF%", "child_msec"); 300 line = line sprintf(" %10s %10s %10s", "max_msec", "max_self", "max_child"); 301 printf("%s %s%s\n", line, "\x1b[35mSOURCE\x1b[36m (FUNCNAME):\x1b[32mLINENO\x1b[36m:\x1b[m", "COMMAND") > file_line; 302 } 303 304 function lines_text_print(info, _, line) { 305 line = sprintf("%8d %8d %8d", info["count"], info["substep_count"], info["allstep_count"]); 306 line = line sprintf(" %10.3f %-6s %10.3f %-6s %10.3f", info["total_time"], info["total_time_percentage"], info["total_self"], info["total_self_percentage"], info["total_child"]); 307 line = line sprintf(" %10.3f %10.3f %10.3f", info["max_time"], info["max_self"], info["max_child"]); 308 printf("%s %s%s\n", line, info["label"], info["command"]) > file_line; 309 } 310 311 function lines_html_header(_, line) { 312 line = sprintf("<!DOCTYPE html>\n"); 313 line = line sprintf("<title>ble.sh xtrace profiling result</title>\n"); 314 line = line sprintf("<style>table,td,th{border-collapse:collapse;border:1px solid black}td{max-width:40em;}</style>\n"); 315 line = line sprintf("<table>\n"); 316 line = line sprintf("<tr>\n"); 317 line = line sprintf(" <th rowspan=2>count</th>\n"); 318 line = line sprintf(" <th rowspan=2>substep</th>\n"); 319 line = line sprintf(" <th rowspan=2>allstep</th>\n"); 320 line = line sprintf(" <th colspan=3>total (msec)</th>\n"); 321 line = line sprintf(" <th colspan=3>average (msec)</th>\n"); 322 line = line sprintf(" <th colspan=3>max (msec)</th>\n"); 323 line = line sprintf(" <th rowspan=2>command</th>\n", max_cmd); 324 line = line sprintf(" <th rowspan=2>location</th>\n", label); 325 line = line sprintf("</tr>\n"); 326 line = line sprintf("<tr>\n"); 327 line = line sprintf(" <th>sum</th>\n"); 328 line = line sprintf(" <th>self</th>\n"); 329 line = line sprintf(" <th>child</th>\n"); 330 line = line sprintf(" <th>sum</th>\n"); 331 line = line sprintf(" <th>self</th>\n"); 332 line = line sprintf(" <th>child</th>\n"); 333 line = line sprintf(" <th>sum</th>\n"); 334 line = line sprintf(" <th>self</th>\n"); 335 line = line sprintf(" <th>child</th>\n"); 336 line = line sprintf("</tr>\n"); 337 printf("%s", line) > file_line_html; 338 } 339 340 function lines_html_escape(str) { 341 gsub(/&/, "\\&", str); 342 gsub(/</, "\\<", str); 343 gsub(/>/, "\\>", str); 344 return str; 345 } 346 347 function lines_html_print(info, _, line) { 348 line = sprintf("<tr>\n"); 349 line = line sprintf(" <td>%d</td>\n", info["count"]); 350 line = line sprintf(" <td>%d</td>\n", info["substep_count"]); 351 line = line sprintf(" <td>%d</td>\n", info["allstep_count"]); 352 line = line sprintf(" <td>%.3f</td>\n", info["total_time"]); 353 line = line sprintf(" <td>%.3f</td>\n", info["total_self"]); 354 line = line sprintf(" <td>%.3f</td>\n", info["total_child"]); 355 line = line sprintf(" <td>%.3f</td>\n", info["average_time"]); 356 line = line sprintf(" <td>%.3f</td>\n", info["average_self"]); 357 line = line sprintf(" <td>%.3f</td>\n", info["average_child"]) 358 line = line sprintf(" <td>%.3f</td>\n", info["max_time"]); 359 line = line sprintf(" <td>%.3f</td>\n", info["max_self"]); 360 line = line sprintf(" <td>%.3f</td>\n", info["max_child"]); 361 line = line sprintf(" <td>%s</td>\n", lines_html_escape(info["command"])); 362 line = line sprintf(" <td>%s</td>\n", lines_html_escape(info["label"])); 363 line = line sprintf("</tr>\n"); 364 printf("%s", line) > file_line_html; 365 } 366 367 function lines_html_footer() { 368 printf("</table>\n") > file_line_html; 369 } 370 371 function lines_save(_, i, label, count, info, total_time) { 372 lines_text_header(); 373 if (file_line_html) lines_html_header(); 374 375 total_time = 0.0; 376 for (i = 0; i < ilabel; i++) { 377 label = labels[i]; 378 total_time += line_stat[label, "total"] - line_stat[label, "child"]; 379 } 380 total_time *= 0.001; 381 382 for (i = 0; i < ilabel; i++) { 383 label = labels[i]; 384 count = line_stat[label, "count"]; 385 386 info["count"] = count; 387 info["allstep_count"] = line_stat[label, "allstep_count"]; 388 info["substep_count"] = line_stat[label, "substep_count"]; 389 info["substep_time"] = line_stat[label, "substep_time"] * 0.001; 390 391 info["total_time"] = line_stat[label, "total"] * 0.001; 392 info["total_child"] = line_stat[label, "child"] * 0.001; 393 info["total_self"] = info["total_time"] - info["total_child"]; 394 info["total_time_percentage"] = to_percentage(info["total_time"] / total_time); 395 info["total_self_percentage"] = to_percentage(info["total_self"] / total_time); 396 info["average_time"] = info["total_time"] / count; 397 info["average_self"] = info["total_self"] / count; 398 info["average_child"] = info["total_child"] / count 399 info["max_time"] = line_stat[label, "max_time"] * 0.001; 400 info["max_child"] = line_stat[label, "max_child"] * 0.001; 401 info["max_self"] = info["max_time"] - info["max_child"]; 402 403 info["label"] = label; 404 info["command"] = line_stat[label, "max_command"]; 405 406 lines_text_print(info); 407 if (file_line_html) lines_html_print(info); 408 } 409 410 if (file_line_html) lines_html_footer(); 411 } 412 413 function lines_load_line(_, i, s, label, old_max_time, new_max_time) { 414 s = substr($0, index($0, "\x1b[35m")); 415 i = index(s, "\x1b[m"); 416 label = substr(s, 1, i + 2); 417 if (!line_stat[label, "count"]) 418 labels[ilabel++] = label; 419 420 line_stat[label, "count"] += $1; 421 line_stat[label, "substep_count"] += $2; 422 line_stat[label, "allstep_count"] += $3; 423 line_stat[label, "substep_time"] += 0.0; # not saved 424 line_stat[label, "total"] += int($4 * 1000 + 0.5); 425 line_stat[label, "child"] += int($8 * 1000 + 0.5); 426 427 old_max_time = line_stat[label, "max_time"]; 428 new_max_time = int($9 * 1000 + 0.5); 429 if (old_max_time == "" || new_max_time > old_max_time) { 430 line_stat[label, "max_command"] = substr(s, i + 3); 431 line_stat[label, "max_time"] = new_max_time; 432 line_stat[label, "max_child"] = int($11 * 1000 + 0.5); 433 } 434 } 435 436 #-------------------------------------------------------------------------- 437 # func_stat 438 439 function funcs_depth_push(pid, depth, usec, fname, source, _, old_depth) { 440 if (!func_stat[fname, "mark"]++) 441 fnames[ifname++] = fname; 442 443 # old_depth = idepth[pid]; 444 if (funcs_depth_pop(pid, depth, usec)) { 445 func_stk[pid, depth, "fname"] = fname; 446 func_stk[pid, depth, "begin"] = usec; 447 # if (depth > old_depth && proc[pid, "time"]) 448 # func_stk[pid, depth, "begin"] = proc[pid, "time"]; 449 func_stk[pid, depth, "child"] = 0.0; 450 func_stk[pid, depth, "allcall_count"] = 0; 451 func_stk[pid, depth, "subcall_count"] = 0; 452 func_stk[pid, depth, "source"] = source; 453 idepth[pid] = depth; 454 } 455 } 456 457 function funcs_depth_getParent(pid, dep) { 458 for (dep--; dep >= 1; dep--) 459 if (func_stk[pid, dep, "fname"] != "") break; 460 return dep; 461 } 462 463 function funcs_depth_pop(pid, depth, usec, fname, _, dp, label, elapsed, pdp) { 464 for (dp = idepth[pid]; dp >= depth; dp--) { 465 if (dp == depth && fname == func_stk[pid, dp, "fname"]) { 466 idepth[pid] = dp; 467 return 0; # 前の関数の続き 468 } 469 470 fname = func_stk[pid, dp, "fname"]; 471 func_stk[pid, dp, "fname"] = ""; 472 if (fname == "") continue; 473 474 elapsed = usec - func_stk[pid, dp, "begin"]; 475 if (elapsed < 0) elapsed = 0.0; 476 477 func_stat[fname, "count"]++; 478 func_stat[fname, "total"] += elapsed; 479 func_stat[fname, "child"] += func_stk[pid, dp, "child"]; 480 func_stat[fname, "allcall_count"] += func_stk[pid, dp, "allcall_count"]; 481 func_stat[fname, "subcall_count"] += func_stk[pid, dp, "subcall_count"]; 482 if ((pdp = funcs_depth_getParent(pid, dp))) { 483 func_stk[pid, pdp, "child"] += elapsed; 484 func_stk[pid, pdp, "allcall_count"] += 1 + func_stk[pid, dp, "allcall_count"]; 485 func_stk[pid, pdp, "subcall_count"]++; 486 } 487 488 func_stat[fname, "source"] = func_stk[pid, dp, "source"]; # always overwrite 489 max_time = func_stat[fname, "max_time"]; 490 if (max_time == "" || elapsed > max_time) { 491 func_stat[fname, "max_time"] = elapsed; 492 func_stat[fname, "max_child"] = func_stk[pid, dp, "child"]; 493 } 494 } 495 idepth[pid] = dp; 496 return 1; 497 } 498 499 function funcs_text_header(_, line) { 500 line = sprintf("# %6s %8s %8s", "count", "subcall", "allcall"); 501 line = line sprintf(" %10s %-6s %10s %-6s %10s", "total_msec", "TOTAL%", "self_msec", "SELF%", "child_msec"); 502 line = line sprintf(" %10s %10s %10s", "max_msec", "max_self", "max_child"); 503 printf("%s %s (\x1b[35m%s\x1b[m)\n", line, "FUNCNAME", "SOURCE") > file_func; 504 } 505 506 function funcs_text_print(info, _, line) { 507 line = sprintf("%8d %8d %8d", info["count"], info["subcall_count"], info["allcall_count"]); 508 line = line sprintf(" %10.3f %-6s %10.3f %-6s %10.3f", info["total_time"], info["total_time_percentage"], info["total_self"], info["total_self_percentage"], info["total_child"]); 509 line = line sprintf(" %10.3f %10.3f %10.3f", info["max_time"], info["max_self"], info["max_child"]); 510 printf("%s %s (\x1b[35m%s\x1b[m)\n", line, info["fname"], info["source"]) > file_func; 511 } 512 513 function funcs_save(_, i, fname, count, info, total_time) { 514 funcs_text_header(); 515 516 total_time = 0.0; 517 for (i = 0; i < ifname; i++) { 518 fname = fnames[i]; 519 total_time += func_stat[fname, "total"] - func_stat[fname, "child"]; 520 } 521 total_time *= 0.001; 522 523 for (i = 0; i < ifname; i++) { 524 fname = fnames[i]; 525 count = func_stat[fname, "count"]; 526 527 info["count"] = count; 528 info["allcall_count"] = func_stat[fname, "allcall_count"]; 529 info["subcall_count"] = func_stat[fname, "subcall_count"]; 530 531 info["total_time"] = func_stat[fname, "total"] * 0.001; 532 info["total_child"] = func_stat[fname, "child"] * 0.001; 533 info["total_self"] = info["total_time"] - info["total_child"]; 534 info["total_time_percentage"] = to_percentage(info["total_time"] / total_time); 535 info["total_self_percentage"] = to_percentage(info["total_self"] / total_time); 536 info["average_time"] = info["total_time"] / count; 537 info["average_self"] = info["total_self"] / count; 538 info["average_child"] = info["total_child"] / count 539 info["max_time"] = func_stat[fname, "max_time"] * 0.001; 540 info["max_child"] = func_stat[fname, "max_child"] * 0.001; 541 info["max_self"] = info["max_time"] - info["max_child"]; 542 543 info["fname"] = fname; 544 info["source"] = func_stat[fname, "source"]; 545 546 funcs_text_print(info); 547 } 548 } 549 550 function funcs_load_line(_, fname, i, s, old_max_time, new_max_time) { 551 fname = $12; 552 if (!func_stat[fname, "mark"]) { 553 fnames[ifname++] = fname; 554 func_stat[fname, "mark"]++; 555 } 556 557 # extract source 558 i = index($0, "\x1b[35m"); 559 if (i > 0) { 560 s = substr($0, i + 5); 561 i = index(s, "\x1b[m"); 562 func_stat[fname, "source"] = substr(s, 1, i - 1); 563 } 564 565 func_stat[fname, "count"] += $1; 566 func_stat[fname, "subcall_count"] += $2; 567 func_stat[fname, "allcall_count"] += $3; 568 func_stat[fname, "total"] += int($4 * 1000 + 0.5); 569 func_stat[fname, "child"] += int($8 * 1000 + 0.5); 570 571 old_max_time = func_stat[fname, "max_time"]; 572 new_max_time = int($9 * 1000 + 0.5); 573 if (old_max_time == "" || new_max_time > old_max_time) { 574 func_stat[fname, "max_time"] = new_max_time; 575 func_stat[fname, "max_child"] = int($11 * 1000 + 0.5); 576 } 577 } 578 579 #-------------------------------------------------------------------------- 580 581 function flush_stack(_, i) { 582 for (i = 0; i < ipid; i++) { 583 lines_level_pop(pids[i], 1, proc[pids[i], "time"]); 584 funcs_depth_pop(pids[i], 1, proc[pids[i], "time"]); 585 } 586 pids_clear(); 587 } 588 589 mode == "line_stat" { if ($0 ~ /^['"$_ble_term_space"']*[^#'"$_ble_term_space"']/) lines_load_line(); next; } 590 mode == "func_stat" { if ($0 ~ /^['"$_ble_term_space"']*[^#'"$_ble_term_space"']/) funcs_load_line(); next; } 591 592 progress_interval && ++iline % progress_interval == 0 { 593 print "\x1b[A\rble/debug/profiler: collecting information... " int((iline * 100) / nline) "%" >"/dev/stderr"; 594 } 595 596 /^\+/ && index($0, magic) { 597 if (!xtrace_debug_enabled) next; 598 599 parse_line(); 600 if (fname == "(global)") { 601 # flush on user input 602 if (command ~ /^ble-decode\/.hook [0-9]+$/) flush_stack(); 603 604 label = command; 605 sub(/^['"$_ble_term_space"']+|['"$_ble_term_space"'].*/, "", label); 606 label = sprintf("\x1b[35m%s\x1b[36m:\x1b[32m%s\x1b[36m (%s):\x1b[m", source, lineno, label); 607 } 608 609 # register "pid" and "label" to the lists 610 pids_register(pid); 611 lines_level_push(pid, level, usec, label, command); 612 funcs_depth_push(pid, depth, usec, fname, source); 613 proc[pid, "time"] = usec; 614 next; 615 } 616 617 /^---- \[.*\] ble\/base\/xtrace\/restore/ { 618 flush_stack(); 619 xtrace_debug_enabled = 0; 620 } 621 /^---- \[.*\] ble\/base\/xtrace\/adjust/ { 622 xtrace_debug_enabled = 1; 623 } 624 625 END { 626 flush_stack(); 627 print "ble/debug/profiler: writing result..." >"/dev/stderr"; 628 lines_save(); 629 funcs_save(); 630 } 631 ' "${awk_args[@]}" && 632 { 633 LANG=C ble/bin/grep '^#' "$f2.part" 634 LANG=C ble/bin/grep -v '^#' "$f2.part" | ble/bin/sort -nrk4 635 } >| "$f2" && 636 { 637 LANG=C ble/bin/grep '^#' "$f4.part" 638 LANG=C ble/bin/grep -v '^#' "$f4.part" | ble/bin/sort -nrk4 639 } >| "$f4" && 640 ble/bin/rm -f "$f1" "$f2.part" "$f4.part" 641 }