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