1 /* vi:set ts=8 sts=4 sw=4 noet: 2 * 3 * VIM - Vi IMproved by Bram Moolenaar 4 * 5 * Do ":help uganda" in Vim to read copying and usage conditions. 6 * Do ":help credits" in Vim to see a list of people who contributed. 7 * See README.txt for an overview of the Vim source code. 8 */ 9 10 /* 11 * profiler.c: vim script profiler 12 */ 13 14 #include "vim.h" 15 16 #if defined(FEAT_EVAL) || defined(PROTO) 17 # if defined(FEAT_PROFILE) || defined(FEAT_RELTIME) || defined(PROTO) 18 /* 19 * Store the current time in "tm". 20 */ 21 void 22 profile_start(proftime_T *tm) 23 { 24 # ifdef MSWIN 25 QueryPerformanceCounter(tm); 26 # else 27 gettimeofday(tm, NULL); 28 # endif 29 } 30 31 /* 32 * Compute the elapsed time from "tm" till now and store in "tm". 33 */ 34 void 35 profile_end(proftime_T *tm) 36 { 37 proftime_T now; 38 39 # ifdef MSWIN 40 QueryPerformanceCounter(&now); 41 tm->QuadPart = now.QuadPart - tm->QuadPart; 42 # else 43 gettimeofday(&now, NULL); 44 tm->tv_usec = now.tv_usec - tm->tv_usec; 45 tm->tv_sec = now.tv_sec - tm->tv_sec; 46 if (tm->tv_usec < 0) 47 { 48 tm->tv_usec += 1000000; 49 --tm->tv_sec; 50 } 51 # endif 52 } 53 54 /* 55 * Subtract the time "tm2" from "tm". 56 */ 57 void 58 profile_sub(proftime_T *tm, proftime_T *tm2) 59 { 60 # ifdef MSWIN 61 tm->QuadPart -= tm2->QuadPart; 62 # else 63 tm->tv_usec -= tm2->tv_usec; 64 tm->tv_sec -= tm2->tv_sec; 65 if (tm->tv_usec < 0) 66 { 67 tm->tv_usec += 1000000; 68 --tm->tv_sec; 69 } 70 # endif 71 } 72 73 /* 74 * Return a string that represents the time in "tm". 75 * Uses a static buffer! 76 */ 77 char * 78 profile_msg(proftime_T *tm) 79 { 80 static char buf[50]; 81 82 # ifdef MSWIN 83 LARGE_INTEGER fr; 84 85 QueryPerformanceFrequency(&fr); 86 sprintf(buf, "%10.6lf", (double)tm->QuadPart / (double)fr.QuadPart); 87 # else 88 sprintf(buf, "%3ld.%06ld", (long)tm->tv_sec, (long)tm->tv_usec); 89 # endif 90 return buf; 91 } 92 93 # if defined(FEAT_FLOAT) || defined(PROTO) 94 /* 95 * Return a float that represents the time in "tm". 96 */ 97 float_T 98 profile_float(proftime_T *tm) 99 { 100 # ifdef MSWIN 101 LARGE_INTEGER fr; 102 103 QueryPerformanceFrequency(&fr); 104 return (float_T)tm->QuadPart / (float_T)fr.QuadPart; 105 # else 106 return (float_T)tm->tv_sec + (float_T)tm->tv_usec / 1000000.0; 107 # endif 108 } 109 # endif 110 111 /* 112 * Put the time "msec" past now in "tm". 113 */ 114 void 115 profile_setlimit(long msec, proftime_T *tm) 116 { 117 if (msec <= 0) // no limit 118 profile_zero(tm); 119 else 120 { 121 # ifdef MSWIN 122 LARGE_INTEGER fr; 123 124 QueryPerformanceCounter(tm); 125 QueryPerformanceFrequency(&fr); 126 tm->QuadPart += (LONGLONG)((double)msec / 1000.0 * (double)fr.QuadPart); 127 # else 128 long usec; 129 130 gettimeofday(tm, NULL); 131 usec = (long)tm->tv_usec + (long)msec * 1000; 132 tm->tv_usec = usec % 1000000L; 133 tm->tv_sec += usec / 1000000L; 134 # endif 135 } 136 } 137 138 /* 139 * Return TRUE if the current time is past "tm". 140 */ 141 int 142 profile_passed_limit(proftime_T *tm) 143 { 144 proftime_T now; 145 146 # ifdef MSWIN 147 if (tm->QuadPart == 0) // timer was not set 148 return FALSE; 149 QueryPerformanceCounter(&now); 150 return (now.QuadPart > tm->QuadPart); 151 # else 152 if (tm->tv_sec == 0) // timer was not set 153 return FALSE; 154 gettimeofday(&now, NULL); 155 return (now.tv_sec > tm->tv_sec 156 || (now.tv_sec == tm->tv_sec && now.tv_usec > tm->tv_usec)); 157 # endif 158 } 159 160 /* 161 * Set the time in "tm" to zero. 162 */ 163 void 164 profile_zero(proftime_T *tm) 165 { 166 # ifdef MSWIN 167 tm->QuadPart = 0; 168 # else 169 tm->tv_usec = 0; 170 tm->tv_sec = 0; 171 # endif 172 } 173 174 # endif // FEAT_PROFILE || FEAT_RELTIME 175 176 #if defined(FEAT_SYN_HL) && defined(FEAT_RELTIME) && defined(FEAT_FLOAT) && defined(FEAT_PROFILE) 177 # if defined(HAVE_MATH_H) 178 # include <math.h> 179 # endif 180 181 /* 182 * Divide the time "tm" by "count" and store in "tm2". 183 */ 184 void 185 profile_divide(proftime_T *tm, int count, proftime_T *tm2) 186 { 187 if (count == 0) 188 profile_zero(tm2); 189 else 190 { 191 # ifdef MSWIN 192 tm2->QuadPart = tm->QuadPart / count; 193 # else 194 double usec = (tm->tv_sec * 1000000.0 + tm->tv_usec) / count; 195 196 tm2->tv_sec = floor(usec / 1000000.0); 197 tm2->tv_usec = vim_round(usec - (tm2->tv_sec * 1000000.0)); 198 # endif 199 } 200 } 201 #endif 202 203 # if defined(FEAT_PROFILE) || defined(PROTO) 204 /* 205 * Functions for profiling. 206 */ 207 static proftime_T prof_wait_time; 208 209 /* 210 * Add the time "tm2" to "tm". 211 */ 212 void 213 profile_add(proftime_T *tm, proftime_T *tm2) 214 { 215 # ifdef MSWIN 216 tm->QuadPart += tm2->QuadPart; 217 # else 218 tm->tv_usec += tm2->tv_usec; 219 tm->tv_sec += tm2->tv_sec; 220 if (tm->tv_usec >= 1000000) 221 { 222 tm->tv_usec -= 1000000; 223 ++tm->tv_sec; 224 } 225 # endif 226 } 227 228 /* 229 * Add the "self" time from the total time and the children's time. 230 */ 231 void 232 profile_self(proftime_T *self, proftime_T *total, proftime_T *children) 233 { 234 // Check that the result won't be negative. Can happen with recursive 235 // calls. 236 #ifdef MSWIN 237 if (total->QuadPart <= children->QuadPart) 238 return; 239 #else 240 if (total->tv_sec < children->tv_sec 241 || (total->tv_sec == children->tv_sec 242 && total->tv_usec <= children->tv_usec)) 243 return; 244 #endif 245 profile_add(self, total); 246 profile_sub(self, children); 247 } 248 249 /* 250 * Get the current waittime. 251 */ 252 static void 253 profile_get_wait(proftime_T *tm) 254 { 255 *tm = prof_wait_time; 256 } 257 258 /* 259 * Subtract the passed waittime since "tm" from "tma". 260 */ 261 void 262 profile_sub_wait(proftime_T *tm, proftime_T *tma) 263 { 264 proftime_T tm3 = prof_wait_time; 265 266 profile_sub(&tm3, tm); 267 profile_sub(tma, &tm3); 268 } 269 270 /* 271 * Return TRUE if "tm1" and "tm2" are equal. 272 */ 273 static int 274 profile_equal(proftime_T *tm1, proftime_T *tm2) 275 { 276 # ifdef MSWIN 277 return (tm1->QuadPart == tm2->QuadPart); 278 # else 279 return (tm1->tv_usec == tm2->tv_usec && tm1->tv_sec == tm2->tv_sec); 280 # endif 281 } 282 283 /* 284 * Return <0, 0 or >0 if "tm1" < "tm2", "tm1" == "tm2" or "tm1" > "tm2" 285 */ 286 int 287 profile_cmp(const proftime_T *tm1, const proftime_T *tm2) 288 { 289 # ifdef MSWIN 290 return (int)(tm2->QuadPart - tm1->QuadPart); 291 # else 292 if (tm1->tv_sec == tm2->tv_sec) 293 return tm2->tv_usec - tm1->tv_usec; 294 return tm2->tv_sec - tm1->tv_sec; 295 # endif 296 } 297 298 static char_u *profile_fname = NULL; 299 static proftime_T pause_time; 300 301 /* 302 * ":profile cmd args" 303 */ 304 void 305 ex_profile(exarg_T *eap) 306 { 307 char_u *e; 308 int len; 309 310 e = skiptowhite(eap->arg); 311 len = (int)(e - eap->arg); 312 e = skipwhite(e); 313 314 if (len == 5 && STRNCMP(eap->arg, "start", 5) == 0 && *e != NUL) 315 { 316 vim_free(profile_fname); 317 profile_fname = expand_env_save_opt(e, TRUE); 318 do_profiling = PROF_YES; 319 profile_zero(&prof_wait_time); 320 set_vim_var_nr(VV_PROFILING, 1L); 321 } 322 else if (do_profiling == PROF_NONE) 323 emsg(_("E750: First use \":profile start {fname}\"")); 324 else if (STRCMP(eap->arg, "pause") == 0) 325 { 326 if (do_profiling == PROF_YES) 327 profile_start(&pause_time); 328 do_profiling = PROF_PAUSED; 329 } 330 else if (STRCMP(eap->arg, "continue") == 0) 331 { 332 if (do_profiling == PROF_PAUSED) 333 { 334 profile_end(&pause_time); 335 profile_add(&prof_wait_time, &pause_time); 336 } 337 do_profiling = PROF_YES; 338 } 339 else 340 { 341 // The rest is similar to ":breakadd". 342 ex_breakadd(eap); 343 } 344 } 345 346 // Command line expansion for :profile. 347 static enum 348 { 349 PEXP_SUBCMD, // expand :profile sub-commands 350 PEXP_FUNC // expand :profile func {funcname} 351 } pexpand_what; 352 353 static char *pexpand_cmds[] = { 354 "start", 355 #define PROFCMD_START 0 356 "pause", 357 #define PROFCMD_PAUSE 1 358 "continue", 359 #define PROFCMD_CONTINUE 2 360 "func", 361 #define PROFCMD_FUNC 3 362 "file", 363 #define PROFCMD_FILE 4 364 NULL 365 #define PROFCMD_LAST 5 366 }; 367 368 /* 369 * Function given to ExpandGeneric() to obtain the profile command 370 * specific expansion. 371 */ 372 char_u * 373 get_profile_name(expand_T *xp UNUSED, int idx) 374 { 375 switch (pexpand_what) 376 { 377 case PEXP_SUBCMD: 378 return (char_u *)pexpand_cmds[idx]; 379 // case PEXP_FUNC: TODO 380 default: 381 return NULL; 382 } 383 } 384 385 /* 386 * Handle command line completion for :profile command. 387 */ 388 void 389 set_context_in_profile_cmd(expand_T *xp, char_u *arg) 390 { 391 char_u *end_subcmd; 392 393 // Default: expand subcommands. 394 xp->xp_context = EXPAND_PROFILE; 395 pexpand_what = PEXP_SUBCMD; 396 xp->xp_pattern = arg; 397 398 end_subcmd = skiptowhite(arg); 399 if (*end_subcmd == NUL) 400 return; 401 402 if (end_subcmd - arg == 5 && STRNCMP(arg, "start", 5) == 0) 403 { 404 xp->xp_context = EXPAND_FILES; 405 xp->xp_pattern = skipwhite(end_subcmd); 406 return; 407 } 408 409 // TODO: expand function names after "func" 410 xp->xp_context = EXPAND_NOTHING; 411 } 412 413 static proftime_T inchar_time; 414 415 /* 416 * Called when starting to wait for the user to type a character. 417 */ 418 void 419 prof_inchar_enter(void) 420 { 421 profile_start(&inchar_time); 422 } 423 424 /* 425 * Called when finished waiting for the user to type a character. 426 */ 427 void 428 prof_inchar_exit(void) 429 { 430 profile_end(&inchar_time); 431 profile_add(&prof_wait_time, &inchar_time); 432 } 433 434 435 /* 436 * Return TRUE when a function defined in the current script should be 437 * profiled. 438 */ 439 int 440 prof_def_func(void) 441 { 442 if (current_sctx.sc_sid > 0) 443 return SCRIPT_ITEM(current_sctx.sc_sid)->sn_pr_force; 444 return FALSE; 445 } 446 447 /* 448 * Print the count and times for one function or function line. 449 */ 450 static void 451 prof_func_line( 452 FILE *fd, 453 int count, 454 proftime_T *total, 455 proftime_T *self, 456 int prefer_self) // when equal print only self time 457 { 458 if (count > 0) 459 { 460 fprintf(fd, "%5d ", count); 461 if (prefer_self && profile_equal(total, self)) 462 fprintf(fd, " "); 463 else 464 fprintf(fd, "%s ", profile_msg(total)); 465 if (!prefer_self && profile_equal(total, self)) 466 fprintf(fd, " "); 467 else 468 fprintf(fd, "%s ", profile_msg(self)); 469 } 470 else 471 fprintf(fd, " "); 472 } 473 474 static void 475 prof_sort_list( 476 FILE *fd, 477 ufunc_T **sorttab, 478 int st_len, 479 char *title, 480 int prefer_self) // when equal print only self time 481 { 482 int i; 483 ufunc_T *fp; 484 485 fprintf(fd, "FUNCTIONS SORTED ON %s TIME\n", title); 486 fprintf(fd, "count total (s) self (s) function\n"); 487 for (i = 0; i < 20 && i < st_len; ++i) 488 { 489 fp = sorttab[i]; 490 prof_func_line(fd, fp->uf_tm_count, &fp->uf_tm_total, &fp->uf_tm_self, 491 prefer_self); 492 if (fp->uf_name[0] == K_SPECIAL) 493 fprintf(fd, " <SNR>%s()\n", fp->uf_name + 3); 494 else 495 fprintf(fd, " %s()\n", fp->uf_name); 496 } 497 fprintf(fd, "\n"); 498 } 499 500 /* 501 * Compare function for total time sorting. 502 */ 503 static int 504 prof_total_cmp(const void *s1, const void *s2) 505 { 506 ufunc_T *p1, *p2; 507 508 p1 = *(ufunc_T **)s1; 509 p2 = *(ufunc_T **)s2; 510 return profile_cmp(&p1->uf_tm_total, &p2->uf_tm_total); 511 } 512 513 /* 514 * Compare function for self time sorting. 515 */ 516 static int 517 prof_self_cmp(const void *s1, const void *s2) 518 { 519 ufunc_T *p1, *p2; 520 521 p1 = *(ufunc_T **)s1; 522 p2 = *(ufunc_T **)s2; 523 return profile_cmp(&p1->uf_tm_self, &p2->uf_tm_self); 524 } 525 526 /* 527 * Start profiling function "fp". 528 */ 529 void 530 func_do_profile(ufunc_T *fp) 531 { 532 int len = fp->uf_lines.ga_len; 533 534 if (!fp->uf_prof_initialized) 535 { 536 if (len == 0) 537 len = 1; // avoid getting error for allocating zero bytes 538 fp->uf_tm_count = 0; 539 profile_zero(&fp->uf_tm_self); 540 profile_zero(&fp->uf_tm_total); 541 if (fp->uf_tml_count == NULL) 542 fp->uf_tml_count = ALLOC_CLEAR_MULT(int, len); 543 if (fp->uf_tml_total == NULL) 544 fp->uf_tml_total = ALLOC_CLEAR_MULT(proftime_T, len); 545 if (fp->uf_tml_self == NULL) 546 fp->uf_tml_self = ALLOC_CLEAR_MULT(proftime_T, len); 547 fp->uf_tml_idx = -1; 548 if (fp->uf_tml_count == NULL || fp->uf_tml_total == NULL 549 || fp->uf_tml_self == NULL) 550 return; // out of memory 551 fp->uf_prof_initialized = TRUE; 552 } 553 554 fp->uf_profiling = TRUE; 555 } 556 557 /* 558 * Prepare profiling for entering a child or something else that is not 559 * counted for the script/function itself. 560 * Should always be called in pair with prof_child_exit(). 561 */ 562 void 563 prof_child_enter( 564 proftime_T *tm) // place to store waittime 565 { 566 funccall_T *fc = get_current_funccal(); 567 568 if (fc != NULL && fc->func->uf_profiling) 569 profile_start(&fc->prof_child); 570 script_prof_save(tm); 571 } 572 573 /* 574 * Take care of time spent in a child. 575 * Should always be called after prof_child_enter(). 576 */ 577 void 578 prof_child_exit( 579 proftime_T *tm) // where waittime was stored 580 { 581 funccall_T *fc = get_current_funccal(); 582 583 if (fc != NULL && fc->func->uf_profiling) 584 { 585 profile_end(&fc->prof_child); 586 profile_sub_wait(tm, &fc->prof_child); // don't count waiting time 587 profile_add(&fc->func->uf_tm_children, &fc->prof_child); 588 profile_add(&fc->func->uf_tml_children, &fc->prof_child); 589 } 590 script_prof_restore(tm); 591 } 592 593 /* 594 * Called when starting to read a function line. 595 * "sourcing_lnum" must be correct! 596 * When skipping lines it may not actually be executed, but we won't find out 597 * until later and we need to store the time now. 598 */ 599 void 600 func_line_start(void *cookie) 601 { 602 funccall_T *fcp = (funccall_T *)cookie; 603 ufunc_T *fp = fcp->func; 604 605 if (fp->uf_profiling && SOURCING_LNUM >= 1 606 && SOURCING_LNUM <= fp->uf_lines.ga_len) 607 { 608 fp->uf_tml_idx = SOURCING_LNUM - 1; 609 // Skip continuation lines. 610 while (fp->uf_tml_idx > 0 && FUNCLINE(fp, fp->uf_tml_idx) == NULL) 611 --fp->uf_tml_idx; 612 fp->uf_tml_execed = FALSE; 613 profile_start(&fp->uf_tml_start); 614 profile_zero(&fp->uf_tml_children); 615 profile_get_wait(&fp->uf_tml_wait); 616 } 617 } 618 619 /* 620 * Called when actually executing a function line. 621 */ 622 void 623 func_line_exec(void *cookie) 624 { 625 funccall_T *fcp = (funccall_T *)cookie; 626 ufunc_T *fp = fcp->func; 627 628 if (fp->uf_profiling && fp->uf_tml_idx >= 0) 629 fp->uf_tml_execed = TRUE; 630 } 631 632 /* 633 * Called when done with a function line. 634 */ 635 void 636 func_line_end(void *cookie) 637 { 638 funccall_T *fcp = (funccall_T *)cookie; 639 ufunc_T *fp = fcp->func; 640 641 if (fp->uf_profiling && fp->uf_tml_idx >= 0) 642 { 643 if (fp->uf_tml_execed) 644 { 645 ++fp->uf_tml_count[fp->uf_tml_idx]; 646 profile_end(&fp->uf_tml_start); 647 profile_sub_wait(&fp->uf_tml_wait, &fp->uf_tml_start); 648 profile_add(&fp->uf_tml_total[fp->uf_tml_idx], &fp->uf_tml_start); 649 profile_self(&fp->uf_tml_self[fp->uf_tml_idx], &fp->uf_tml_start, 650 &fp->uf_tml_children); 651 } 652 fp->uf_tml_idx = -1; 653 } 654 } 655 656 /* 657 * Dump the profiling results for all functions in file "fd". 658 */ 659 static void 660 func_dump_profile(FILE *fd) 661 { 662 hashtab_T *functbl; 663 hashitem_T *hi; 664 int todo; 665 ufunc_T *fp; 666 int i; 667 ufunc_T **sorttab; 668 int st_len = 0; 669 char_u *p; 670 671 functbl = func_tbl_get(); 672 todo = (int)functbl->ht_used; 673 if (todo == 0) 674 return; // nothing to dump 675 676 sorttab = ALLOC_MULT(ufunc_T *, todo); 677 678 for (hi = functbl->ht_array; todo > 0; ++hi) 679 { 680 if (!HASHITEM_EMPTY(hi)) 681 { 682 --todo; 683 fp = HI2UF(hi); 684 if (fp->uf_prof_initialized) 685 { 686 if (sorttab != NULL) 687 sorttab[st_len++] = fp; 688 689 if (fp->uf_name[0] == K_SPECIAL) 690 fprintf(fd, "FUNCTION <SNR>%s()\n", fp->uf_name + 3); 691 else 692 fprintf(fd, "FUNCTION %s()\n", fp->uf_name); 693 if (fp->uf_script_ctx.sc_sid > 0) 694 { 695 p = home_replace_save(NULL, 696 get_scriptname(fp->uf_script_ctx.sc_sid)); 697 if (p != NULL) 698 { 699 fprintf(fd, " Defined: %s:%ld\n", 700 p, (long)fp->uf_script_ctx.sc_lnum); 701 vim_free(p); 702 } 703 } 704 if (fp->uf_tm_count == 1) 705 fprintf(fd, "Called 1 time\n"); 706 else 707 fprintf(fd, "Called %d times\n", fp->uf_tm_count); 708 fprintf(fd, "Total time: %s\n", profile_msg(&fp->uf_tm_total)); 709 fprintf(fd, " Self time: %s\n", profile_msg(&fp->uf_tm_self)); 710 fprintf(fd, "\n"); 711 fprintf(fd, "count total (s) self (s)\n"); 712 713 for (i = 0; i < fp->uf_lines.ga_len; ++i) 714 { 715 if (FUNCLINE(fp, i) == NULL) 716 continue; 717 prof_func_line(fd, fp->uf_tml_count[i], 718 &fp->uf_tml_total[i], &fp->uf_tml_self[i], TRUE); 719 fprintf(fd, "%s\n", FUNCLINE(fp, i)); 720 } 721 fprintf(fd, "\n"); 722 } 723 } 724 } 725 726 if (sorttab != NULL && st_len > 0) 727 { 728 qsort((void *)sorttab, (size_t)st_len, sizeof(ufunc_T *), 729 prof_total_cmp); 730 prof_sort_list(fd, sorttab, st_len, "TOTAL", FALSE); 731 qsort((void *)sorttab, (size_t)st_len, sizeof(ufunc_T *), 732 prof_self_cmp); 733 prof_sort_list(fd, sorttab, st_len, "SELF", TRUE); 734 } 735 736 vim_free(sorttab); 737 } 738 739 /* 740 * Start profiling script "fp". 741 */ 742 void 743 script_do_profile(scriptitem_T *si) 744 { 745 si->sn_pr_count = 0; 746 profile_zero(&si->sn_pr_total); 747 profile_zero(&si->sn_pr_self); 748 749 ga_init2(&si->sn_prl_ga, sizeof(sn_prl_T), 100); 750 si->sn_prl_idx = -1; 751 si->sn_prof_on = TRUE; 752 si->sn_pr_nest = 0; 753 } 754 755 /* 756 * Save time when starting to invoke another script or function. 757 */ 758 void 759 script_prof_save( 760 proftime_T *tm) // place to store wait time 761 { 762 scriptitem_T *si; 763 764 if (current_sctx.sc_sid > 0 && current_sctx.sc_sid <= script_items.ga_len) 765 { 766 si = SCRIPT_ITEM(current_sctx.sc_sid); 767 if (si->sn_prof_on && si->sn_pr_nest++ == 0) 768 profile_start(&si->sn_pr_child); 769 } 770 profile_get_wait(tm); 771 } 772 773 /* 774 * Count time spent in children after invoking another script or function. 775 */ 776 void 777 script_prof_restore(proftime_T *tm) 778 { 779 scriptitem_T *si; 780 781 if (current_sctx.sc_sid > 0 && current_sctx.sc_sid <= script_items.ga_len) 782 { 783 si = SCRIPT_ITEM(current_sctx.sc_sid); 784 if (si->sn_prof_on && --si->sn_pr_nest == 0) 785 { 786 profile_end(&si->sn_pr_child); 787 profile_sub_wait(tm, &si->sn_pr_child); // don't count wait time 788 profile_add(&si->sn_pr_children, &si->sn_pr_child); 789 profile_add(&si->sn_prl_children, &si->sn_pr_child); 790 } 791 } 792 } 793 794 /* 795 * Dump the profiling results for all scripts in file "fd". 796 */ 797 static void 798 script_dump_profile(FILE *fd) 799 { 800 int id; 801 scriptitem_T *si; 802 int i; 803 FILE *sfd; 804 sn_prl_T *pp; 805 806 for (id = 1; id <= script_items.ga_len; ++id) 807 { 808 si = SCRIPT_ITEM(id); 809 if (si->sn_prof_on) 810 { 811 fprintf(fd, "SCRIPT %s\n", si->sn_name); 812 if (si->sn_pr_count == 1) 813 fprintf(fd, "Sourced 1 time\n"); 814 else 815 fprintf(fd, "Sourced %d times\n", si->sn_pr_count); 816 fprintf(fd, "Total time: %s\n", profile_msg(&si->sn_pr_total)); 817 fprintf(fd, " Self time: %s\n", profile_msg(&si->sn_pr_self)); 818 fprintf(fd, "\n"); 819 fprintf(fd, "count total (s) self (s)\n"); 820 821 sfd = mch_fopen((char *)si->sn_name, "r"); 822 if (sfd == NULL) 823 fprintf(fd, "Cannot open file!\n"); 824 else 825 { 826 // Keep going till the end of file, so that trailing 827 // continuation lines are listed. 828 for (i = 0; ; ++i) 829 { 830 if (vim_fgets(IObuff, IOSIZE, sfd)) 831 break; 832 // When a line has been truncated, append NL, taking care 833 // of multi-byte characters . 834 if (IObuff[IOSIZE - 2] != NUL && IObuff[IOSIZE - 2] != NL) 835 { 836 int n = IOSIZE - 2; 837 838 if (enc_utf8) 839 { 840 // Move to the first byte of this char. 841 // utf_head_off() doesn't work, because it checks 842 // for a truncated character. 843 while (n > 0 && (IObuff[n] & 0xc0) == 0x80) 844 --n; 845 } 846 else if (has_mbyte) 847 n -= mb_head_off(IObuff, IObuff + n); 848 IObuff[n] = NL; 849 IObuff[n + 1] = NUL; 850 } 851 if (i < si->sn_prl_ga.ga_len 852 && (pp = &PRL_ITEM(si, i))->snp_count > 0) 853 { 854 fprintf(fd, "%5d ", pp->snp_count); 855 if (profile_equal(&pp->sn_prl_total, &pp->sn_prl_self)) 856 fprintf(fd, " "); 857 else 858 fprintf(fd, "%s ", profile_msg(&pp->sn_prl_total)); 859 fprintf(fd, "%s ", profile_msg(&pp->sn_prl_self)); 860 } 861 else 862 fprintf(fd, " "); 863 fprintf(fd, "%s", IObuff); 864 } 865 fclose(sfd); 866 } 867 fprintf(fd, "\n"); 868 } 869 } 870 } 871 872 /* 873 * Dump the profiling info. 874 */ 875 void 876 profile_dump(void) 877 { 878 FILE *fd; 879 880 if (profile_fname != NULL) 881 { 882 fd = mch_fopen((char *)profile_fname, "w"); 883 if (fd == NULL) 884 semsg(_(e_notopen), profile_fname); 885 else 886 { 887 script_dump_profile(fd); 888 func_dump_profile(fd); 889 fclose(fd); 890 } 891 } 892 } 893 894 /* 895 * Called when starting to read a script line. 896 * "sourcing_lnum" must be correct! 897 * When skipping lines it may not actually be executed, but we won't find out 898 * until later and we need to store the time now. 899 */ 900 void 901 script_line_start(void) 902 { 903 scriptitem_T *si; 904 sn_prl_T *pp; 905 906 if (current_sctx.sc_sid <= 0 || current_sctx.sc_sid > script_items.ga_len) 907 return; 908 si = SCRIPT_ITEM(current_sctx.sc_sid); 909 if (si->sn_prof_on && SOURCING_LNUM >= 1) 910 { 911 // Grow the array before starting the timer, so that the time spent 912 // here isn't counted. 913 (void)ga_grow(&si->sn_prl_ga, 914 (int)(SOURCING_LNUM - si->sn_prl_ga.ga_len)); 915 si->sn_prl_idx = SOURCING_LNUM - 1; 916 while (si->sn_prl_ga.ga_len <= si->sn_prl_idx 917 && si->sn_prl_ga.ga_len < si->sn_prl_ga.ga_maxlen) 918 { 919 // Zero counters for a line that was not used before. 920 pp = &PRL_ITEM(si, si->sn_prl_ga.ga_len); 921 pp->snp_count = 0; 922 profile_zero(&pp->sn_prl_total); 923 profile_zero(&pp->sn_prl_self); 924 ++si->sn_prl_ga.ga_len; 925 } 926 si->sn_prl_execed = FALSE; 927 profile_start(&si->sn_prl_start); 928 profile_zero(&si->sn_prl_children); 929 profile_get_wait(&si->sn_prl_wait); 930 } 931 } 932 933 /* 934 * Called when actually executing a function line. 935 */ 936 void 937 script_line_exec(void) 938 { 939 scriptitem_T *si; 940 941 if (current_sctx.sc_sid <= 0 || current_sctx.sc_sid > script_items.ga_len) 942 return; 943 si = SCRIPT_ITEM(current_sctx.sc_sid); 944 if (si->sn_prof_on && si->sn_prl_idx >= 0) 945 si->sn_prl_execed = TRUE; 946 } 947 948 /* 949 * Called when done with a script line. 950 */ 951 void 952 script_line_end(void) 953 { 954 scriptitem_T *si; 955 sn_prl_T *pp; 956 957 if (current_sctx.sc_sid <= 0 || current_sctx.sc_sid > script_items.ga_len) 958 return; 959 si = SCRIPT_ITEM(current_sctx.sc_sid); 960 if (si->sn_prof_on && si->sn_prl_idx >= 0 961 && si->sn_prl_idx < si->sn_prl_ga.ga_len) 962 { 963 if (si->sn_prl_execed) 964 { 965 pp = &PRL_ITEM(si, si->sn_prl_idx); 966 ++pp->snp_count; 967 profile_end(&si->sn_prl_start); 968 profile_sub_wait(&si->sn_prl_wait, &si->sn_prl_start); 969 profile_add(&pp->sn_prl_total, &si->sn_prl_start); 970 profile_self(&pp->sn_prl_self, &si->sn_prl_start, 971 &si->sn_prl_children); 972 } 973 si->sn_prl_idx = -1; 974 } 975 } 976 # endif // FEAT_PROFILE 977 978 #endif 979