Mercurial > vim

comparison src/profiler.c @ 17370:ba06a1c42274 v8.1.1684

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
patch 8.1.1684: profiling functionality is spread out commit https://github.com/vim/vim/commit/fa55cfc69d2b14761e2a8bd85bc1e0d82df770aa Author: Bram Moolenaar <Bram@vim.org> Date: Sat Jul 13 22:59:32 2019 +0200 patch 8.1.1684: profiling functionality is spread out Problem: Profiling functionality is spread out. Solution: Put profiling functionality in profiling.c. (Yegappan Lakshmanan, closes #4666)
author Bram Moolenaar <Bram@vim.org>
date Sat, 13 Jul 2019 23:00:06 +0200
parents
children 8f44c630c366
comparison
equal deleted inserted replaced
17369:4b97e0731720 17370:ba06a1c42274
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 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 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 /*
414 * Dump the profiling info.
415 */
416 void
417 profile_dump(void)
418 {
419 FILE *fd;
420
421 if (profile_fname != NULL)
422 {
423 fd = mch_fopen((char *)profile_fname, "w");
424 if (fd == NULL)
425 semsg(_(e_notopen), profile_fname);
426 else
427 {
428 script_dump_profile(fd);
429 func_dump_profile(fd);
430 fclose(fd);
431 }
432 }
433 }
434
435 static proftime_T inchar_time;
436
437 /*
438 * Called when starting to wait for the user to type a character.
439 */
440 void
441 prof_inchar_enter(void)
442 {
443 profile_start(&inchar_time);
444 }
445
446 /*
447 * Called when finished waiting for the user to type a character.
448 */
449 void
450 prof_inchar_exit(void)
451 {
452 profile_end(&inchar_time);
453 profile_add(&prof_wait_time, &inchar_time);
454 }
455
456
457 /*
458 * Return TRUE when a function defined in the current script should be
459 * profiled.
460 */
461 int
462 prof_def_func(void)
463 {
464 if (current_sctx.sc_sid > 0)
465 return SCRIPT_ITEM(current_sctx.sc_sid).sn_pr_force;
466 return FALSE;
467 }
468
469 void
470 prof_sort_list(
471 FILE *fd,
472 ufunc_T **sorttab,
473 int st_len,
474 char *title,
475 int prefer_self) /* when equal print only self time */
476 {
477 int i;
478 ufunc_T *fp;
479
480 fprintf(fd, "FUNCTIONS SORTED ON %s TIME\n", title);
481 fprintf(fd, "count total (s) self (s) function\n");
482 for (i = 0; i < 20 && i < st_len; ++i)
483 {
484 fp = sorttab[i];
485 prof_func_line(fd, fp->uf_tm_count, &fp->uf_tm_total, &fp->uf_tm_self,
486 prefer_self);
487 if (fp->uf_name[0] == K_SPECIAL)
488 fprintf(fd, " <SNR>%s()\n", fp->uf_name + 3);
489 else
490 fprintf(fd, " %s()\n", fp->uf_name);
491 }
492 fprintf(fd, "\n");
493 }
494
495 /*
496 * Print the count and times for one function or function line.
497 */
498 void
499 prof_func_line(
500 FILE *fd,
501 int count,
502 proftime_T *total,
503 proftime_T *self,
504 int prefer_self) /* when equal print only self time */
505 {
506 if (count > 0)
507 {
508 fprintf(fd, "%5d ", count);
509 if (prefer_self && profile_equal(total, self))
510 fprintf(fd, " ");
511 else
512 fprintf(fd, "%s ", profile_msg(total));
513 if (!prefer_self && profile_equal(total, self))
514 fprintf(fd, " ");
515 else
516 fprintf(fd, "%s ", profile_msg(self));
517 }
518 else
519 fprintf(fd, " ");
520 }
521
522 /*
523 * Compare function for total time sorting.
524 */
525 int
526 prof_total_cmp(const void *s1, const void *s2)
527 {
528 ufunc_T *p1, *p2;
529
530 p1 = *(ufunc_T **)s1;
531 p2 = *(ufunc_T **)s2;
532 return profile_cmp(&p1->uf_tm_total, &p2->uf_tm_total);
533 }
534
535 /*
536 * Compare function for self time sorting.
537 */
538 int
539 prof_self_cmp(const void *s1, const void *s2)
540 {
541 ufunc_T *p1, *p2;
542
543 p1 = *(ufunc_T **)s1;
544 p2 = *(ufunc_T **)s2;
545 return profile_cmp(&p1->uf_tm_self, &p2->uf_tm_self);
546 }
547
548 /*
549 * Start profiling function "fp".
550 */
551 void
552 func_do_profile(ufunc_T *fp)
553 {
554 int len = fp->uf_lines.ga_len;
555
556 if (!fp->uf_prof_initialized)
557 {
558 if (len == 0)
559 len = 1; /* avoid getting error for allocating zero bytes */
560 fp->uf_tm_count = 0;
561 profile_zero(&fp->uf_tm_self);
562 profile_zero(&fp->uf_tm_total);
563 if (fp->uf_tml_count == NULL)
564 fp->uf_tml_count = ALLOC_CLEAR_MULT(int, len);
565 if (fp->uf_tml_total == NULL)
566 fp->uf_tml_total = ALLOC_CLEAR_MULT(proftime_T, len);
567 if (fp->uf_tml_self == NULL)
568 fp->uf_tml_self = ALLOC_CLEAR_MULT(proftime_T, len);
569 fp->uf_tml_idx = -1;
570 if (fp->uf_tml_count == NULL || fp->uf_tml_total == NULL
571 || fp->uf_tml_self == NULL)
572 return; /* out of memory */
573 fp->uf_prof_initialized = TRUE;
574 }
575
576 fp->uf_profiling = TRUE;
577 }
578
579 /*
580 * Prepare profiling for entering a child or something else that is not
581 * counted for the script/function itself.
582 * Should always be called in pair with prof_child_exit().
583 */
584 void
585 prof_child_enter(
586 proftime_T *tm) /* place to store waittime */
587 {
588 funccall_T *fc = get_current_funccal();
589
590 if (fc != NULL && fc->func->uf_profiling)
591 profile_start(&fc->prof_child);
592 script_prof_save(tm);
593 }
594
595 /*
596 * Take care of time spent in a child.
597 * Should always be called after prof_child_enter().
598 */
599 void
600 prof_child_exit(
601 proftime_T *tm) /* where waittime was stored */
602 {
603 funccall_T *fc = get_current_funccal();
604
605 if (fc != NULL && fc->func->uf_profiling)
606 {
607 profile_end(&fc->prof_child);
608 profile_sub_wait(tm, &fc->prof_child); /* don't count waiting time */
609 profile_add(&fc->func->uf_tm_children, &fc->prof_child);
610 profile_add(&fc->func->uf_tml_children, &fc->prof_child);
611 }
612 script_prof_restore(tm);
613 }
614
615 /*
616 * Called when starting to read a function line.
617 * "sourcing_lnum" must be correct!
618 * When skipping lines it may not actually be executed, but we won't find out
619 * until later and we need to store the time now.
620 */
621 void
622 func_line_start(void *cookie)
623 {
624 funccall_T *fcp = (funccall_T *)cookie;
625 ufunc_T *fp = fcp->func;
626
627 if (fp->uf_profiling && sourcing_lnum >= 1
628 && sourcing_lnum <= fp->uf_lines.ga_len)
629 {
630 fp->uf_tml_idx = sourcing_lnum - 1;
631 /* Skip continuation lines. */
632 while (fp->uf_tml_idx > 0 && FUNCLINE(fp, fp->uf_tml_idx) == NULL)
633 --fp->uf_tml_idx;
634 fp->uf_tml_execed = FALSE;
635 profile_start(&fp->uf_tml_start);
636 profile_zero(&fp->uf_tml_children);
637 profile_get_wait(&fp->uf_tml_wait);
638 }
639 }
640
641 /*
642 * Called when actually executing a function line.
643 */
644 void
645 func_line_exec(void *cookie)
646 {
647 funccall_T *fcp = (funccall_T *)cookie;
648 ufunc_T *fp = fcp->func;
649
650 if (fp->uf_profiling && fp->uf_tml_idx >= 0)
651 fp->uf_tml_execed = TRUE;
652 }
653
654 /*
655 * Called when done with a function line.
656 */
657 void
658 func_line_end(void *cookie)
659 {
660 funccall_T *fcp = (funccall_T *)cookie;
661 ufunc_T *fp = fcp->func;
662
663 if (fp->uf_profiling && fp->uf_tml_idx >= 0)
664 {
665 if (fp->uf_tml_execed)
666 {
667 ++fp->uf_tml_count[fp->uf_tml_idx];
668 profile_end(&fp->uf_tml_start);
669 profile_sub_wait(&fp->uf_tml_wait, &fp->uf_tml_start);
670 profile_add(&fp->uf_tml_total[fp->uf_tml_idx], &fp->uf_tml_start);
671 profile_self(&fp->uf_tml_self[fp->uf_tml_idx], &fp->uf_tml_start,
672 &fp->uf_tml_children);
673 }
674 fp->uf_tml_idx = -1;
675 }
676 }
677 # endif /* FEAT_PROFILE */
678
679 #endif