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 * When calling a function: may initialize for profiling. 559 */ 560 void 561 profile_may_start_func(profinfo_T *info, ufunc_T *fp, funccall_T *fc) 562 { 563 if (do_profiling == PROF_YES) 564 { 565 if (!fp->uf_profiling && has_profiling(FALSE, fp->uf_name, NULL)) 566 { 567 info->pi_started_profiling = TRUE; 568 func_do_profile(fp); 569 } 570 if (fp->uf_profiling 571 || (fc->caller != NULL && fc->caller->func->uf_profiling)) 572 { 573 ++fp->uf_tm_count; 574 profile_start(&info->pi_call_start); 575 profile_zero(&fp->uf_tm_children); 576 } 577 script_prof_save(&info->pi_wait_start); 578 } 579 } 580 581 /* 582 * After calling a function: may handle profiling. profile_may_start_func() 583 * must have been called previously. 584 */ 585 void 586 profile_may_end_func(profinfo_T *info, ufunc_T *fp, funccall_T *fc) 587 { 588 profile_end(&info->pi_call_start); 589 profile_sub_wait(&info->pi_wait_start, &info->pi_call_start); 590 profile_add(&fp->uf_tm_total, &info->pi_call_start); 591 profile_self(&fp->uf_tm_self, &info->pi_call_start, &fp->uf_tm_children); 592 if (fc->caller != NULL && fc->caller->func->uf_profiling) 593 { 594 profile_add(&fc->caller->func->uf_tm_children, &info->pi_call_start); 595 profile_add(&fc->caller->func->uf_tml_children, &info->pi_call_start); 596 } 597 if (info->pi_started_profiling) 598 // make a ":profdel func" stop profiling the function 599 fp->uf_profiling = FALSE; 600 } 601 602 /* 603 * Prepare profiling for entering a child or something else that is not 604 * counted for the script/function itself. 605 * Should always be called in pair with prof_child_exit(). 606 */ 607 void 608 prof_child_enter( 609 proftime_T *tm) // place to store waittime 610 { 611 funccall_T *fc = get_current_funccal(); 612 613 if (fc != NULL && fc->func->uf_profiling) 614 profile_start(&fc->prof_child); 615 script_prof_save(tm); 616 } 617 618 /* 619 * Take care of time spent in a child. 620 * Should always be called after prof_child_enter(). 621 */ 622 void 623 prof_child_exit( 624 proftime_T *tm) // where waittime was stored 625 { 626 funccall_T *fc = get_current_funccal(); 627 628 if (fc != NULL && fc->func->uf_profiling) 629 { 630 profile_end(&fc->prof_child); 631 profile_sub_wait(tm, &fc->prof_child); // don't count waiting time 632 profile_add(&fc->func->uf_tm_children, &fc->prof_child); 633 profile_add(&fc->func->uf_tml_children, &fc->prof_child); 634 } 635 script_prof_restore(tm); 636 } 637 638 /* 639 * Called when starting to read a function line. 640 * "sourcing_lnum" must be correct! 641 * When skipping lines it may not actually be executed, but we won't find out 642 * until later and we need to store the time now. 643 */ 644 void 645 func_line_start(void *cookie, long lnum) 646 { 647 funccall_T *fcp = (funccall_T *)cookie; 648 ufunc_T *fp = fcp->func; 649 650 if (fp->uf_profiling && lnum >= 1 && lnum <= fp->uf_lines.ga_len) 651 { 652 fp->uf_tml_idx = lnum - 1; 653 // Skip continuation lines. 654 while (fp->uf_tml_idx > 0 && FUNCLINE(fp, fp->uf_tml_idx) == NULL) 655 --fp->uf_tml_idx; 656 fp->uf_tml_execed = FALSE; 657 profile_start(&fp->uf_tml_start); 658 profile_zero(&fp->uf_tml_children); 659 profile_get_wait(&fp->uf_tml_wait); 660 } 661 } 662 663 /* 664 * Called when actually executing a function line. 665 */ 666 void 667 func_line_exec(void *cookie) 668 { 669 funccall_T *fcp = (funccall_T *)cookie; 670 ufunc_T *fp = fcp->func; 671 672 if (fp->uf_profiling && fp->uf_tml_idx >= 0) 673 fp->uf_tml_execed = TRUE; 674 } 675 676 /* 677 * Called when done with a function line. 678 */ 679 void 680 func_line_end(void *cookie) 681 { 682 funccall_T *fcp = (funccall_T *)cookie; 683 ufunc_T *fp = fcp->func; 684 685 if (fp->uf_profiling && fp->uf_tml_idx >= 0) 686 { 687 if (fp->uf_tml_execed) 688 { 689 ++fp->uf_tml_count[fp->uf_tml_idx]; 690 profile_end(&fp->uf_tml_start); 691 profile_sub_wait(&fp->uf_tml_wait, &fp->uf_tml_start); 692 profile_add(&fp->uf_tml_total[fp->uf_tml_idx], &fp->uf_tml_start); 693 profile_self(&fp->uf_tml_self[fp->uf_tml_idx], &fp->uf_tml_start, 694 &fp->uf_tml_children); 695 } 696 fp->uf_tml_idx = -1; 697 } 698 } 699 700 /* 701 * Dump the profiling results for all functions in file "fd". 702 */ 703 static void 704 func_dump_profile(FILE *fd) 705 { 706 hashtab_T *functbl; 707 hashitem_T *hi; 708 int todo; 709 ufunc_T *fp; 710 int i; 711 ufunc_T **sorttab; 712 int st_len = 0; 713 char_u *p; 714 715 functbl = func_tbl_get(); 716 todo = (int)functbl->ht_used; 717 if (todo == 0) 718 return; // nothing to dump 719 720 sorttab = ALLOC_MULT(ufunc_T *, todo); 721 722 for (hi = functbl->ht_array; todo > 0; ++hi) 723 { 724 if (!HASHITEM_EMPTY(hi)) 725 { 726 --todo; 727 fp = HI2UF(hi); 728 if (fp->uf_prof_initialized) 729 { 730 if (sorttab != NULL) 731 sorttab[st_len++] = fp; 732 733 if (fp->uf_name[0] == K_SPECIAL) 734 fprintf(fd, "FUNCTION <SNR>%s()\n", fp->uf_name + 3); 735 else 736 fprintf(fd, "FUNCTION %s()\n", fp->uf_name); 737 if (fp->uf_script_ctx.sc_sid > 0) 738 { 739 p = home_replace_save(NULL, 740 get_scriptname(fp->uf_script_ctx.sc_sid)); 741 if (p != NULL) 742 { 743 fprintf(fd, " Defined: %s:%ld\n", 744 p, (long)fp->uf_script_ctx.sc_lnum); 745 vim_free(p); 746 } 747 } 748 if (fp->uf_tm_count == 1) 749 fprintf(fd, "Called 1 time\n"); 750 else 751 fprintf(fd, "Called %d times\n", fp->uf_tm_count); 752 fprintf(fd, "Total time: %s\n", profile_msg(&fp->uf_tm_total)); 753 fprintf(fd, " Self time: %s\n", profile_msg(&fp->uf_tm_self)); 754 fprintf(fd, "\n"); 755 fprintf(fd, "count total (s) self (s)\n"); 756 757 for (i = 0; i < fp->uf_lines.ga_len; ++i) 758 { 759 if (FUNCLINE(fp, i) == NULL) 760 continue; 761 prof_func_line(fd, fp->uf_tml_count[i], 762 &fp->uf_tml_total[i], &fp->uf_tml_self[i], TRUE); 763 fprintf(fd, "%s\n", FUNCLINE(fp, i)); 764 } 765 fprintf(fd, "\n"); 766 } 767 } 768 } 769 770 if (sorttab != NULL && st_len > 0) 771 { 772 qsort((void *)sorttab, (size_t)st_len, sizeof(ufunc_T *), 773 prof_total_cmp); 774 prof_sort_list(fd, sorttab, st_len, "TOTAL", FALSE); 775 qsort((void *)sorttab, (size_t)st_len, sizeof(ufunc_T *), 776 prof_self_cmp); 777 prof_sort_list(fd, sorttab, st_len, "SELF", TRUE); 778 } 779 780 vim_free(sorttab); 781 } 782 783 /* 784 * Start profiling script "fp". 785 */ 786 void 787 script_do_profile(scriptitem_T *si) 788 { 789 si->sn_pr_count = 0; 790 profile_zero(&si->sn_pr_total); 791 profile_zero(&si->sn_pr_self); 792 793 ga_init2(&si->sn_prl_ga, sizeof(sn_prl_T), 100); 794 si->sn_prl_idx = -1; 795 si->sn_prof_on = TRUE; 796 si->sn_pr_nest = 0; 797 } 798 799 /* 800 * Save time when starting to invoke another script or function. 801 */ 802 void 803 script_prof_save( 804 proftime_T *tm) // place to store wait time 805 { 806 scriptitem_T *si; 807 808 if (SCRIPT_ID_VALID(current_sctx.sc_sid)) 809 { 810 si = SCRIPT_ITEM(current_sctx.sc_sid); 811 if (si->sn_prof_on && si->sn_pr_nest++ == 0) 812 profile_start(&si->sn_pr_child); 813 } 814 profile_get_wait(tm); 815 } 816 817 /* 818 * Count time spent in children after invoking another script or function. 819 */ 820 void 821 script_prof_restore(proftime_T *tm) 822 { 823 scriptitem_T *si; 824 825 if (SCRIPT_ID_VALID(current_sctx.sc_sid)) 826 { 827 si = SCRIPT_ITEM(current_sctx.sc_sid); 828 if (si->sn_prof_on && --si->sn_pr_nest == 0) 829 { 830 profile_end(&si->sn_pr_child); 831 profile_sub_wait(tm, &si->sn_pr_child); // don't count wait time 832 profile_add(&si->sn_pr_children, &si->sn_pr_child); 833 profile_add(&si->sn_prl_children, &si->sn_pr_child); 834 } 835 } 836 } 837 838 /* 839 * Dump the profiling results for all scripts in file "fd". 840 */ 841 static void 842 script_dump_profile(FILE *fd) 843 { 844 int id; 845 scriptitem_T *si; 846 int i; 847 FILE *sfd; 848 sn_prl_T *pp; 849 850 for (id = 1; id <= script_items.ga_len; ++id) 851 { 852 si = SCRIPT_ITEM(id); 853 if (si->sn_prof_on) 854 { 855 fprintf(fd, "SCRIPT %s\n", si->sn_name); 856 if (si->sn_pr_count == 1) 857 fprintf(fd, "Sourced 1 time\n"); 858 else 859 fprintf(fd, "Sourced %d times\n", si->sn_pr_count); 860 fprintf(fd, "Total time: %s\n", profile_msg(&si->sn_pr_total)); 861 fprintf(fd, " Self time: %s\n", profile_msg(&si->sn_pr_self)); 862 fprintf(fd, "\n"); 863 fprintf(fd, "count total (s) self (s)\n"); 864 865 sfd = mch_fopen((char *)si->sn_name, "r"); 866 if (sfd == NULL) 867 fprintf(fd, "Cannot open file!\n"); 868 else 869 { 870 // Keep going till the end of file, so that trailing 871 // continuation lines are listed. 872 for (i = 0; ; ++i) 873 { 874 if (vim_fgets(IObuff, IOSIZE, sfd)) 875 break; 876 // When a line has been truncated, append NL, taking care 877 // of multi-byte characters . 878 if (IObuff[IOSIZE - 2] != NUL && IObuff[IOSIZE - 2] != NL) 879 { 880 int n = IOSIZE - 2; 881 882 if (enc_utf8) 883 { 884 // Move to the first byte of this char. 885 // utf_head_off() doesn't work, because it checks 886 // for a truncated character. 887 while (n > 0 && (IObuff[n] & 0xc0) == 0x80) 888 --n; 889 } 890 else if (has_mbyte) 891 n -= mb_head_off(IObuff, IObuff + n); 892 IObuff[n] = NL; 893 IObuff[n + 1] = NUL; 894 } 895 if (i < si->sn_prl_ga.ga_len 896 && (pp = &PRL_ITEM(si, i))->snp_count > 0) 897 { 898 fprintf(fd, "%5d ", pp->snp_count); 899 if (profile_equal(&pp->sn_prl_total, &pp->sn_prl_self)) 900 fprintf(fd, " "); 901 else 902 fprintf(fd, "%s ", profile_msg(&pp->sn_prl_total)); 903 fprintf(fd, "%s ", profile_msg(&pp->sn_prl_self)); 904 } 905 else 906 fprintf(fd, " "); 907 fprintf(fd, "%s", IObuff); 908 } 909 fclose(sfd); 910 } 911 fprintf(fd, "\n"); 912 } 913 } 914 } 915 916 /* 917 * Dump the profiling info. 918 */ 919 void 920 profile_dump(void) 921 { 922 FILE *fd; 923 924 if (profile_fname != NULL) 925 { 926 fd = mch_fopen((char *)profile_fname, "w"); 927 if (fd == NULL) 928 semsg(_(e_notopen), profile_fname); 929 else 930 { 931 script_dump_profile(fd); 932 func_dump_profile(fd); 933 fclose(fd); 934 } 935 } 936 } 937 938 /* 939 * Called when starting to read a script line. 940 * "sourcing_lnum" must be correct! 941 * When skipping lines it may not actually be executed, but we won't find out 942 * until later and we need to store the time now. 943 */ 944 void 945 script_line_start(void) 946 { 947 scriptitem_T *si; 948 sn_prl_T *pp; 949 950 if (!SCRIPT_ID_VALID(current_sctx.sc_sid)) 951 return; 952 si = SCRIPT_ITEM(current_sctx.sc_sid); 953 if (si->sn_prof_on && SOURCING_LNUM >= 1) 954 { 955 // Grow the array before starting the timer, so that the time spent 956 // here isn't counted. 957 (void)ga_grow(&si->sn_prl_ga, 958 (int)(SOURCING_LNUM - si->sn_prl_ga.ga_len)); 959 si->sn_prl_idx = SOURCING_LNUM - 1; 960 while (si->sn_prl_ga.ga_len <= si->sn_prl_idx 961 && si->sn_prl_ga.ga_len < si->sn_prl_ga.ga_maxlen) 962 { 963 // Zero counters for a line that was not used before. 964 pp = &PRL_ITEM(si, si->sn_prl_ga.ga_len); 965 pp->snp_count = 0; 966 profile_zero(&pp->sn_prl_total); 967 profile_zero(&pp->sn_prl_self); 968 ++si->sn_prl_ga.ga_len; 969 } 970 si->sn_prl_execed = FALSE; 971 profile_start(&si->sn_prl_start); 972 profile_zero(&si->sn_prl_children); 973 profile_get_wait(&si->sn_prl_wait); 974 } 975 } 976 977 /* 978 * Called when actually executing a function line. 979 */ 980 void 981 script_line_exec(void) 982 { 983 scriptitem_T *si; 984 985 if (!SCRIPT_ID_VALID(current_sctx.sc_sid)) 986 return; 987 si = SCRIPT_ITEM(current_sctx.sc_sid); 988 if (si->sn_prof_on && si->sn_prl_idx >= 0) 989 si->sn_prl_execed = TRUE; 990 } 991 992 /* 993 * Called when done with a script line. 994 */ 995 void 996 script_line_end(void) 997 { 998 scriptitem_T *si; 999 sn_prl_T *pp; 1000 1001 if (!SCRIPT_ID_VALID(current_sctx.sc_sid)) 1002 return; 1003 si = SCRIPT_ITEM(current_sctx.sc_sid); 1004 if (si->sn_prof_on && si->sn_prl_idx >= 0 1005 && si->sn_prl_idx < si->sn_prl_ga.ga_len) 1006 { 1007 if (si->sn_prl_execed) 1008 { 1009 pp = &PRL_ITEM(si, si->sn_prl_idx); 1010 ++pp->snp_count; 1011 profile_end(&si->sn_prl_start); 1012 profile_sub_wait(&si->sn_prl_wait, &si->sn_prl_start); 1013 profile_add(&pp->sn_prl_total, &si->sn_prl_start); 1014 profile_self(&pp->sn_prl_self, &si->sn_prl_start, 1015 &si->sn_prl_children); 1016 } 1017 si->sn_prl_idx = -1; 1018 } 1019 } 1020 # endif // FEAT_PROFILE 1021 1022 #endif 1023