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
profile_start(proftime_T * tm)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
profile_end(proftime_T * tm)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
profile_sub(proftime_T * tm,proftime_T * tm2)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 *
profile_msg(proftime_T * tm)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
profile_float(proftime_T * tm)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
profile_setlimit(long msec,proftime_T * tm)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
profile_passed_limit(proftime_T * tm)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
profile_zero(proftime_T * tm)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
profile_divide(proftime_T * tm,int count,proftime_T * tm2)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
profile_add(proftime_T * tm,proftime_T * tm2)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
profile_self(proftime_T * self,proftime_T * total,proftime_T * children)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
profile_get_wait(proftime_T * tm)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
profile_sub_wait(proftime_T * tm,proftime_T * tma)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
profile_equal(proftime_T * tm1,proftime_T * tm2)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
profile_cmp(const proftime_T * tm1,const proftime_T * tm2)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
ex_profile(exarg_T * eap)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 *
get_profile_name(expand_T * xp UNUSED,int idx)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
set_context_in_profile_cmd(expand_T * xp,char_u * arg)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
prof_inchar_enter(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
prof_inchar_exit(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
prof_def_func(void)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
prof_func_line(FILE * fd,int count,proftime_T * total,proftime_T * self,int prefer_self)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
prof_sort_list(FILE * fd,ufunc_T ** sorttab,int st_len,char * title,int prefer_self)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
prof_total_cmp(const void * s1,const void * s2)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
prof_self_cmp(const void * s1,const void * s2)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
func_do_profile(ufunc_T * fp)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 * Save time when starting to invoke another script or function.
559 */
560 static void
script_prof_save(proftime_T * tm)561 script_prof_save(
562 proftime_T *tm) // place to store wait time
563 {
564 scriptitem_T *si;
565
566 if (SCRIPT_ID_VALID(current_sctx.sc_sid))
567 {
568 si = SCRIPT_ITEM(current_sctx.sc_sid);
569 if (si->sn_prof_on && si->sn_pr_nest++ == 0)
570 profile_start(&si->sn_pr_child);
571 }
572 profile_get_wait(tm);
573 }
574
575 /*
576 * When calling a function: may initialize for profiling.
577 */
578 void
profile_may_start_func(profinfo_T * info,ufunc_T * fp,ufunc_T * caller)579 profile_may_start_func(profinfo_T *info, ufunc_T *fp, ufunc_T *caller)
580 {
581 if (!fp->uf_profiling && has_profiling(FALSE, fp->uf_name, NULL))
582 {
583 info->pi_started_profiling = TRUE;
584 func_do_profile(fp);
585 }
586 if (fp->uf_profiling || (caller != NULL && caller->uf_profiling))
587 {
588 ++fp->uf_tm_count;
589 profile_start(&info->pi_call_start);
590 profile_zero(&fp->uf_tm_children);
591 }
592 script_prof_save(&info->pi_wait_start);
593 }
594
595 /*
596 * After calling a function: may handle profiling. profile_may_start_func()
597 * must have been called previously.
598 */
599 void
profile_may_end_func(profinfo_T * info,ufunc_T * fp,ufunc_T * caller)600 profile_may_end_func(profinfo_T *info, ufunc_T *fp, ufunc_T *caller)
601 {
602 profile_end(&info->pi_call_start);
603 profile_sub_wait(&info->pi_wait_start, &info->pi_call_start);
604 profile_add(&fp->uf_tm_total, &info->pi_call_start);
605 profile_self(&fp->uf_tm_self, &info->pi_call_start, &fp->uf_tm_children);
606 if (caller != NULL && caller->uf_profiling)
607 {
608 profile_add(&caller->uf_tm_children, &info->pi_call_start);
609 profile_add(&caller->uf_tml_children, &info->pi_call_start);
610 }
611 if (info->pi_started_profiling)
612 // make a ":profdel func" stop profiling the function
613 fp->uf_profiling = FALSE;
614 }
615
616 /*
617 * Prepare profiling for entering a child or something else that is not
618 * counted for the script/function itself.
619 * Should always be called in pair with prof_child_exit().
620 */
621 void
prof_child_enter(proftime_T * tm)622 prof_child_enter(
623 proftime_T *tm) // place to store waittime
624 {
625 funccall_T *fc = get_current_funccal();
626
627 if (fc != NULL && fc->func->uf_profiling)
628 profile_start(&fc->prof_child);
629 script_prof_save(tm);
630 }
631
632 /*
633 * Take care of time spent in a child.
634 * Should always be called after prof_child_enter().
635 */
636 void
prof_child_exit(proftime_T * tm)637 prof_child_exit(
638 proftime_T *tm) // where waittime was stored
639 {
640 funccall_T *fc = get_current_funccal();
641
642 if (fc != NULL && fc->func->uf_profiling)
643 {
644 profile_end(&fc->prof_child);
645 profile_sub_wait(tm, &fc->prof_child); // don't count waiting time
646 profile_add(&fc->func->uf_tm_children, &fc->prof_child);
647 profile_add(&fc->func->uf_tml_children, &fc->prof_child);
648 }
649 script_prof_restore(tm);
650 }
651
652 /*
653 * Called when starting to read a function line.
654 * "sourcing_lnum" must be correct!
655 * When skipping lines it may not actually be executed, but we won't find out
656 * until later and we need to store the time now.
657 */
658 void
func_line_start(void * cookie,long lnum)659 func_line_start(void *cookie, long lnum)
660 {
661 funccall_T *fcp = (funccall_T *)cookie;
662 ufunc_T *fp = fcp->func;
663
664 if (fp->uf_profiling && lnum >= 1 && lnum <= fp->uf_lines.ga_len)
665 {
666 fp->uf_tml_idx = lnum - 1;
667 // Skip continuation lines.
668 while (fp->uf_tml_idx > 0 && FUNCLINE(fp, fp->uf_tml_idx) == NULL)
669 --fp->uf_tml_idx;
670 fp->uf_tml_execed = FALSE;
671 profile_start(&fp->uf_tml_start);
672 profile_zero(&fp->uf_tml_children);
673 profile_get_wait(&fp->uf_tml_wait);
674 }
675 }
676
677 /*
678 * Called when actually executing a function line.
679 */
680 void
func_line_exec(void * cookie)681 func_line_exec(void *cookie)
682 {
683 funccall_T *fcp = (funccall_T *)cookie;
684 ufunc_T *fp = fcp->func;
685
686 if (fp->uf_profiling && fp->uf_tml_idx >= 0)
687 fp->uf_tml_execed = TRUE;
688 }
689
690 /*
691 * Called when done with a function line.
692 */
693 void
func_line_end(void * cookie)694 func_line_end(void *cookie)
695 {
696 funccall_T *fcp = (funccall_T *)cookie;
697 ufunc_T *fp = fcp->func;
698
699 if (fp->uf_profiling && fp->uf_tml_idx >= 0)
700 {
701 if (fp->uf_tml_execed)
702 {
703 ++fp->uf_tml_count[fp->uf_tml_idx];
704 profile_end(&fp->uf_tml_start);
705 profile_sub_wait(&fp->uf_tml_wait, &fp->uf_tml_start);
706 profile_add(&fp->uf_tml_total[fp->uf_tml_idx], &fp->uf_tml_start);
707 profile_self(&fp->uf_tml_self[fp->uf_tml_idx], &fp->uf_tml_start,
708 &fp->uf_tml_children);
709 }
710 fp->uf_tml_idx = -1;
711 }
712 }
713
714 /*
715 * Dump the profiling results for all functions in file "fd".
716 */
717 static void
func_dump_profile(FILE * fd)718 func_dump_profile(FILE *fd)
719 {
720 hashtab_T *functbl;
721 hashitem_T *hi;
722 int todo;
723 ufunc_T *fp;
724 int i;
725 ufunc_T **sorttab;
726 int st_len = 0;
727 char_u *p;
728
729 functbl = func_tbl_get();
730 todo = (int)functbl->ht_used;
731 if (todo == 0)
732 return; // nothing to dump
733
734 sorttab = ALLOC_MULT(ufunc_T *, todo);
735
736 for (hi = functbl->ht_array; todo > 0; ++hi)
737 {
738 if (!HASHITEM_EMPTY(hi))
739 {
740 --todo;
741 fp = HI2UF(hi);
742 if (fp->uf_prof_initialized)
743 {
744 if (sorttab != NULL)
745 sorttab[st_len++] = fp;
746
747 if (fp->uf_name[0] == K_SPECIAL)
748 fprintf(fd, "FUNCTION <SNR>%s()\n", fp->uf_name + 3);
749 else
750 fprintf(fd, "FUNCTION %s()\n", fp->uf_name);
751 if (fp->uf_script_ctx.sc_sid > 0)
752 {
753 p = home_replace_save(NULL,
754 get_scriptname(fp->uf_script_ctx.sc_sid));
755 if (p != NULL)
756 {
757 fprintf(fd, " Defined: %s:%ld\n",
758 p, (long)fp->uf_script_ctx.sc_lnum);
759 vim_free(p);
760 }
761 }
762 if (fp->uf_tm_count == 1)
763 fprintf(fd, "Called 1 time\n");
764 else
765 fprintf(fd, "Called %d times\n", fp->uf_tm_count);
766 fprintf(fd, "Total time: %s\n", profile_msg(&fp->uf_tm_total));
767 fprintf(fd, " Self time: %s\n", profile_msg(&fp->uf_tm_self));
768 fprintf(fd, "\n");
769 fprintf(fd, "count total (s) self (s)\n");
770
771 for (i = 0; i < fp->uf_lines.ga_len; ++i)
772 {
773 if (FUNCLINE(fp, i) == NULL)
774 continue;
775 prof_func_line(fd, fp->uf_tml_count[i],
776 &fp->uf_tml_total[i], &fp->uf_tml_self[i], TRUE);
777 fprintf(fd, "%s\n", FUNCLINE(fp, i));
778 }
779 fprintf(fd, "\n");
780 }
781 }
782 }
783
784 if (sorttab != NULL && st_len > 0)
785 {
786 qsort((void *)sorttab, (size_t)st_len, sizeof(ufunc_T *),
787 prof_total_cmp);
788 prof_sort_list(fd, sorttab, st_len, "TOTAL", FALSE);
789 qsort((void *)sorttab, (size_t)st_len, sizeof(ufunc_T *),
790 prof_self_cmp);
791 prof_sort_list(fd, sorttab, st_len, "SELF", TRUE);
792 }
793
794 vim_free(sorttab);
795 }
796
797 /*
798 * Start profiling script "fp".
799 */
800 void
script_do_profile(scriptitem_T * si)801 script_do_profile(scriptitem_T *si)
802 {
803 si->sn_pr_count = 0;
804 profile_zero(&si->sn_pr_total);
805 profile_zero(&si->sn_pr_self);
806
807 ga_init2(&si->sn_prl_ga, sizeof(sn_prl_T), 100);
808 si->sn_prl_idx = -1;
809 si->sn_prof_on = TRUE;
810 si->sn_pr_nest = 0;
811 }
812
813 /*
814 * Count time spent in children after invoking another script or function.
815 */
816 void
script_prof_restore(proftime_T * tm)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
script_dump_profile(FILE * fd)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
profile_dump(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
script_line_start(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
script_line_exec(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
script_line_end(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