To: vim_dev@googlegroups.com Subject: Patch 9.0.1411 Fcc: outbox From: Bram Moolenaar Mime-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ------------ Patch 9.0.1411 Problem: Accuracy of profiling is not optimal. Solution: Use CLOCK_MONOTONIC if possible. (Ernie Rael, closes #12129) Files: runtime/doc/builtin.txt, runtime/doc/repeat.txt, src/evalfunc.c, src/profiler.c, src/time.c, src/vim.h, src/testdir/test_profile.vim, src/testdir/test_sleep.vim *** ../vim-9.0.1410/runtime/doc/builtin.txt 2023-03-12 21:20:51.433254189 +0000 --- runtime/doc/builtin.txt 2023-03-16 21:33:55.555630105 +0000 *************** *** 7143,7149 **** call MyFunction() echo reltimestr(reltime(start)) < Note that overhead for the commands will be added to the time. ! The accuracy depends on the system. Leading spaces are used to make the string align nicely. You can use split() to remove it. > echo split(reltimestr(reltime(start)))[0] --- 7150,7157 ---- call MyFunction() echo reltimestr(reltime(start)) < Note that overhead for the commands will be added to the time. ! The accuracy depends on the system. Use reltimefloat() for the ! greatest accuracy which is nanoseconds on some systems. Leading spaces are used to make the string align nicely. You can use split() to remove it. > echo split(reltimestr(reltime(start)))[0] *************** *** 10744,10749 **** --- 10754,10760 ---- postscript Compiled with PostScript file printing. printer Compiled with |:hardcopy| support. profile Compiled with |:profile| support. + prof_nsec Profile results are in nano seconds. python Python 2.x interface available. |has-python| python_compiled Compiled with Python 2.x interface. |has-python| python_dynamic Python 2.x interface is dynamically loaded. |has-python| *** ../vim-9.0.1410/runtime/doc/repeat.txt 2022-08-24 16:30:30.686752454 +0100 --- runtime/doc/repeat.txt 2023-03-16 21:37:11.683454392 +0000 *************** *** 1135,1143 **** Profiling should give a good indication of where time is spent, but keep in mind there are various things that may clobber the results: ! - The accuracy of the time measured depends on the gettimeofday() system ! function. It may only be as accurate as 1/100 second, even though the times ! are displayed in micro seconds. - Real elapsed time is measured, if other processes are busy they may cause delays at unpredictable moments. You may want to run the profiling several --- 1148,1157 ---- Profiling should give a good indication of where time is spent, but keep in mind there are various things that may clobber the results: ! - The accuracy of the time measured depends on the gettimeofday(), or ! clock_gettime if available, system function. The accuracy ranges from 1/100 ! second to nano seconds. With clock_gettime the times are displayed in nano ! seconds, otherwise micro seconds. You can use `has("prof_nsec")`. - Real elapsed time is measured, if other processes are busy they may cause delays at unpredictable moments. You may want to run the profiling several *** ../vim-9.0.1410/src/evalfunc.c 2023-03-07 17:45:07.180247902 +0000 --- src/evalfunc.c 2023-03-16 21:33:55.555630105 +0000 *************** *** 6145,6150 **** --- 6145,6157 ---- 0 #endif }, + {"prof_nsec", + #ifdef HAVE_TIMER_CREATE + 1 + #else + 0 + #endif + }, {"reltime", #ifdef FEAT_RELTIME 1 *************** *** 8226,8232 **** # if defined(MSWIN) *x = (UINT32_T)res.LowPart; # else ! *x = (UINT32_T)res.tv_usec; # endif #else *x = vim_time(); --- 8233,8239 ---- # if defined(MSWIN) *x = (UINT32_T)res.LowPart; # else ! *x = (UINT32_T)res.tv_fsec; # endif #else *x = vim_time(); *** ../vim-9.0.1410/src/profiler.c 2023-03-07 17:13:47.313107772 +0000 --- src/profiler.c 2023-03-16 21:39:38.055350193 +0000 *************** *** 24,30 **** # ifdef MSWIN QueryPerformanceCounter(tm); # else ! gettimeofday(tm, NULL); # endif } --- 24,30 ---- # ifdef MSWIN QueryPerformanceCounter(tm); # else ! PROF_GET_TIME(tm); # endif } *************** *** 40,51 **** QueryPerformanceCounter(&now); tm->QuadPart = now.QuadPart - tm->QuadPart; # else ! gettimeofday(&now, NULL); ! tm->tv_usec = now.tv_usec - tm->tv_usec; tm->tv_sec = now.tv_sec - tm->tv_sec; ! if (tm->tv_usec < 0) { ! tm->tv_usec += 1000000; --tm->tv_sec; } # endif --- 40,51 ---- QueryPerformanceCounter(&now); tm->QuadPart = now.QuadPart - tm->QuadPart; # else ! PROF_GET_TIME(&now); ! tm->tv_fsec = now.tv_fsec - tm->tv_fsec; tm->tv_sec = now.tv_sec - tm->tv_sec; ! if (tm->tv_fsec < 0) { ! tm->tv_fsec += TV_FSEC_SEC; --tm->tv_sec; } # endif *************** *** 60,70 **** # ifdef MSWIN tm->QuadPart -= tm2->QuadPart; # else ! tm->tv_usec -= tm2->tv_usec; tm->tv_sec -= tm2->tv_sec; ! if (tm->tv_usec < 0) { ! tm->tv_usec += 1000000; --tm->tv_sec; } # endif --- 60,70 ---- # ifdef MSWIN tm->QuadPart -= tm2->QuadPart; # else ! tm->tv_fsec -= tm2->tv_fsec; tm->tv_sec -= tm2->tv_sec; ! if (tm->tv_fsec < 0) { ! tm->tv_fsec += TV_FSEC_SEC; --tm->tv_sec; } # endif *************** *** 85,91 **** QueryPerformanceFrequency(&fr); sprintf(buf, "%10.6lf", (double)tm->QuadPart / (double)fr.QuadPart); # else ! sprintf(buf, "%3ld.%06ld", (long)tm->tv_sec, (long)tm->tv_usec); # endif return buf; } --- 85,91 ---- QueryPerformanceFrequency(&fr); sprintf(buf, "%10.6lf", (double)tm->QuadPart / (double)fr.QuadPart); # else ! sprintf(buf, PROF_TIME_FORMAT, (long)tm->tv_sec, (long)tm->tv_fsec); # endif return buf; } *************** *** 102,108 **** QueryPerformanceFrequency(&fr); return (float_T)tm->QuadPart / (float_T)fr.QuadPart; # else ! return (float_T)tm->tv_sec + (float_T)tm->tv_usec / 1000000.0; # endif } --- 102,108 ---- QueryPerformanceFrequency(&fr); return (float_T)tm->QuadPart / (float_T)fr.QuadPart; # else ! return (float_T)tm->tv_sec + (float_T)tm->tv_fsec / (float_T)TV_FSEC_SEC; # endif } *************** *** 123,134 **** QueryPerformanceFrequency(&fr); tm->QuadPart += (LONGLONG)((double)msec / 1000.0 * (double)fr.QuadPart); # else ! long usec; ! gettimeofday(tm, NULL); ! usec = (long)tm->tv_usec + (long)msec * 1000; ! tm->tv_usec = usec % 1000000L; ! tm->tv_sec += usec / 1000000L; # endif } } --- 123,134 ---- QueryPerformanceFrequency(&fr); tm->QuadPart += (LONGLONG)((double)msec / 1000.0 * (double)fr.QuadPart); # else ! long fsec; ! PROF_GET_TIME(tm); ! fsec = (long)tm->tv_fsec + (long)msec * (TV_FSEC_SEC / 1000); ! tm->tv_fsec = fsec % (long)TV_FSEC_SEC; ! tm->tv_sec += fsec / (long)TV_FSEC_SEC; # endif } } *************** *** 149,157 **** # else if (tm->tv_sec == 0) // timer was not set return FALSE; ! gettimeofday(&now, NULL); return (now.tv_sec > tm->tv_sec ! || (now.tv_sec == tm->tv_sec && now.tv_usec > tm->tv_usec)); # endif } --- 149,157 ---- # else if (tm->tv_sec == 0) // timer was not set return FALSE; ! PROF_GET_TIME(&now); return (now.tv_sec > tm->tv_sec ! || (now.tv_sec == tm->tv_sec && now.tv_fsec > tm->tv_fsec)); # endif } *************** *** 164,170 **** # ifdef MSWIN tm->QuadPart = 0; # else ! tm->tv_usec = 0; tm->tv_sec = 0; # endif } --- 164,170 ---- # ifdef MSWIN tm->QuadPart = 0; # else ! tm->tv_fsec = 0; tm->tv_sec = 0; # endif } *************** *** 189,198 **** # ifdef MSWIN tm2->QuadPart = tm->QuadPart / count; # else ! double usec = (tm->tv_sec * 1000000.0 + tm->tv_usec) / count; ! tm2->tv_sec = floor(usec / 1000000.0); ! tm2->tv_usec = vim_round(usec - (tm2->tv_sec * 1000000.0)); # endif } } --- 189,199 ---- # ifdef MSWIN tm2->QuadPart = tm->QuadPart / count; # else ! double fsec = (tm->tv_sec * (float_T)TV_FSEC_SEC + tm->tv_fsec) ! / count; ! tm2->tv_sec = floor(fsec / (float_T)TV_FSEC_SEC); ! tm2->tv_fsec = vim_round(fsec - (tm2->tv_sec * (float_T)TV_FSEC_SEC)); # endif } } *************** *** 213,223 **** # ifdef MSWIN tm->QuadPart += tm2->QuadPart; # else ! tm->tv_usec += tm2->tv_usec; tm->tv_sec += tm2->tv_sec; ! if (tm->tv_usec >= 1000000) { ! tm->tv_usec -= 1000000; ++tm->tv_sec; } # endif --- 214,224 ---- # ifdef MSWIN tm->QuadPart += tm2->QuadPart; # else ! tm->tv_fsec += tm2->tv_fsec; tm->tv_sec += tm2->tv_sec; ! if (tm->tv_fsec >= TV_FSEC_SEC) { ! tm->tv_fsec -= TV_FSEC_SEC; ++tm->tv_sec; } # endif *************** *** 237,243 **** #else if (total->tv_sec < children->tv_sec || (total->tv_sec == children->tv_sec ! && total->tv_usec <= children->tv_usec)) return; #endif profile_add(self, total); --- 238,244 ---- #else if (total->tv_sec < children->tv_sec || (total->tv_sec == children->tv_sec ! && total->tv_fsec <= children->tv_fsec)) return; #endif profile_add(self, total); *************** *** 274,280 **** # ifdef MSWIN return (tm1->QuadPart == tm2->QuadPart); # else ! return (tm1->tv_usec == tm2->tv_usec && tm1->tv_sec == tm2->tv_sec); # endif } --- 275,281 ---- # ifdef MSWIN return (tm1->QuadPart == tm2->QuadPart); # else ! return (tm1->tv_fsec == tm2->tv_fsec && tm1->tv_sec == tm2->tv_sec); # endif } *************** *** 288,294 **** return (int)(tm2->QuadPart - tm1->QuadPart); # else if (tm1->tv_sec == tm2->tv_sec) ! return tm2->tv_usec - tm1->tv_usec; return tm2->tv_sec - tm1->tv_sec; # endif } --- 289,295 ---- return (int)(tm2->QuadPart - tm1->QuadPart); # else if (tm1->tv_sec == tm2->tv_sec) ! return tm2->tv_fsec - tm1->tv_fsec; return tm2->tv_sec - tm1->tv_sec; # endif } *************** *** 551,566 **** { fprintf(fd, "%5d ", count); if (prefer_self && profile_equal(total, self)) ! fprintf(fd, " "); else fprintf(fd, "%s ", profile_msg(total)); if (!prefer_self && profile_equal(total, self)) ! fprintf(fd, " "); else fprintf(fd, "%s ", profile_msg(self)); } else ! fprintf(fd, " "); } static void --- 552,567 ---- { fprintf(fd, "%5d ", count); if (prefer_self && profile_equal(total, self)) ! fprintf(fd, PROF_TIME_BLANK); else fprintf(fd, "%s ", profile_msg(total)); if (!prefer_self && profile_equal(total, self)) ! fprintf(fd, PROF_TIME_BLANK); else fprintf(fd, "%s ", profile_msg(self)); } else ! fprintf(fd, " %s%s", PROF_TIME_BLANK, PROF_TIME_BLANK); } static void *************** *** 575,581 **** ufunc_T *fp; fprintf(fd, "FUNCTIONS SORTED ON %s TIME\n", title); ! fprintf(fd, "count total (s) self (s) function\n"); for (i = 0; i < 20 && i < st_len; ++i) { fp = sorttab[i]; --- 576,582 ---- ufunc_T *fp; fprintf(fd, "FUNCTIONS SORTED ON %s TIME\n", title); ! fprintf(fd, "%s function\n", PROF_TOTALS_HEADER); for (i = 0; i < 20 && i < st_len; ++i) { fp = sorttab[i]; *************** *** 858,864 **** fprintf(fd, "Total time: %s\n", profile_msg(&fp->uf_tm_total)); fprintf(fd, " Self time: %s\n", profile_msg(&fp->uf_tm_self)); fprintf(fd, "\n"); ! fprintf(fd, "count total (s) self (s)\n"); for (i = 0; i < fp->uf_lines.ga_len; ++i) { --- 859,865 ---- fprintf(fd, "Total time: %s\n", profile_msg(&fp->uf_tm_total)); fprintf(fd, " Self time: %s\n", profile_msg(&fp->uf_tm_self)); fprintf(fd, "\n"); ! fprintf(fd, "%s\n", PROF_TOTALS_HEADER); for (i = 0; i < fp->uf_lines.ga_len; ++i) { *************** *** 948,954 **** fprintf(fd, "Total time: %s\n", profile_msg(&si->sn_pr_total)); fprintf(fd, " Self time: %s\n", profile_msg(&si->sn_pr_self)); fprintf(fd, "\n"); ! fprintf(fd, "count total (s) self (s)\n"); sfd = mch_fopen((char *)si->sn_name, "r"); if (sfd == NULL) --- 949,955 ---- fprintf(fd, "Total time: %s\n", profile_msg(&si->sn_pr_total)); fprintf(fd, " Self time: %s\n", profile_msg(&si->sn_pr_self)); fprintf(fd, "\n"); ! fprintf(fd, "%s\n", PROF_TOTALS_HEADER); sfd = mch_fopen((char *)si->sn_name, "r"); if (sfd == NULL) *** ../vim-9.0.1410/src/time.c 2023-02-21 14:27:34.524360386 +0000 --- src/time.c 2023-03-16 21:39:51.399341550 +0000 *************** *** 163,169 **** tm->LowPart = n2; # else tm->tv_sec = n1; ! tm->tv_usec = n2; # endif return error ? FAIL : OK; } --- 163,169 ---- tm->LowPart = n2; # else tm->tv_sec = n1; ! tm->tv_fsec = n2; # endif return error ? FAIL : OK; } *************** *** 222,228 **** n2 = res.LowPart; # else n1 = res.tv_sec; ! n2 = res.tv_usec; # endif list_append_number(rettv->vval.v_list, (varnumber_T)n1); list_append_number(rettv->vval.v_list, (varnumber_T)n2); --- 222,228 ---- n2 = res.LowPart; # else n1 = res.tv_sec; ! n2 = res.tv_fsec; # endif list_append_number(rettv->vval.v_list, (varnumber_T)n1); list_append_number(rettv->vval.v_list, (varnumber_T)n2); *************** *** 258,263 **** --- 258,264 ---- void f_reltimestr(typval_T *argvars UNUSED, typval_T *rettv) { + static char buf[50]; # ifdef FEAT_RELTIME proftime_T tm; # endif *************** *** 269,275 **** --- 270,284 ---- return; if (list2proftime(&argvars[0], &tm) == OK) + { + # ifdef MSWIN rettv->vval.v_string = vim_strsave((char_u *)profile_msg(&tm)); + # else + long usec = tm.tv_fsec / (TV_FSEC_SEC / 1000000); + sprintf(buf, "%3ld.%06ld", (long)tm.tv_sec, usec); + rettv->vval.v_string = vim_strsave((char_u *)buf); + # endif + } else if (in_vim9script()) emsg(_(e_invalid_argument)); # endif *************** *** 392,398 **** static long last_timer_id = 0; /* ! * Return time left until "due". Negative if past "due". */ long proftime_time_left(proftime_T *due, proftime_T *now) --- 401,407 ---- static long last_timer_id = 0; /* ! * Return time left, in "msec", until "due". Negative if past "due". */ long proftime_time_left(proftime_T *due, proftime_T *now) *************** *** 409,415 **** if (now->tv_sec > due->tv_sec) return 0; return (due->tv_sec - now->tv_sec) * 1000 ! + (due->tv_usec - now->tv_usec) / 1000; # endif } --- 418,424 ---- if (now->tv_sec > due->tv_sec) return 0; return (due->tv_sec - now->tv_sec) * 1000 ! + (due->tv_fsec - now->tv_fsec) / (TV_FSEC_SEC / 1000); # endif } *** ../vim-9.0.1410/src/vim.h 2023-03-10 16:34:27.568958670 +0000 --- src/vim.h 2023-03-16 21:40:01.763334916 +0000 *************** *** 1869,1876 **** --- 1869,1895 ---- #if (defined(FEAT_PROFILE) || defined(FEAT_RELTIME)) && !defined(PROTO) # ifdef MSWIN typedef LARGE_INTEGER proftime_T; + # define PROF_TIME_BLANK " " + # define PROF_TOTALS_HEADER "count total (s) self (s)" # else + // Use tv_fsec for fraction of second (micro or nano) of proftime_T + # if defined(HAVE_TIMER_CREATE) + typedef struct timespec proftime_T; + # define PROF_GET_TIME(tm) clock_gettime(CLOCK_MONOTONIC, tm) + # define tv_fsec tv_nsec + # define TV_FSEC_SEC 1000000000L + # define PROF_TIME_FORMAT "%3ld.%09ld" + # define PROF_TIME_BLANK " " + # define PROF_TOTALS_HEADER "count total (s) self (s)" + # else typedef struct timeval proftime_T; + # define PROF_GET_TIME(tm) gettimeofday(tm, NULL) + # define tv_fsec tv_usec + # define TV_FSEC_SEC 1000000 + # define PROF_TIME_FORMAT "%3ld.%06ld" + # define PROF_TIME_BLANK " " + # define PROF_TOTALS_HEADER "count total (s) self (s)" + # endif # endif #else typedef int proftime_T; // dummy for function prototypes *** ../vim-9.0.1410/src/testdir/test_profile.vim 2023-03-10 18:28:09.065055754 +0000 --- src/testdir/test_profile.vim 2023-03-16 21:33:55.555630105 +0000 *************** *** 6,13 **** source shared.vim source screendump.vim ! let s:header = 'count total (s) self (s)' ! let s:header_func = 'count total (s) self (s) function' func Test_profile_func() call RunProfileFunc('func', 'let', 'let') --- 6,18 ---- source shared.vim source screendump.vim ! if has('prof_nsec') ! let s:header = 'count total (s) self (s)' ! let s:header_func = 'count total (s) self (s) function' ! else ! let s:header = 'count total (s) self (s)' ! let s:header_func = 'count total (s) self (s) function' ! endif func Test_profile_func() call RunProfileFunc('func', 'let', 'let') *** ../vim-9.0.1410/src/testdir/test_sleep.vim 2021-03-13 12:12:42.000000000 +0000 --- src/testdir/test_sleep.vim 2023-03-16 21:33:55.555630105 +0000 *************** *** 1,11 **** " Test for sleep and sleep! commands func! s:get_time_ms() ! let timestr = reltimestr(reltime()) ! let dotidx = stridx(timestr, '.') ! let sec = str2nr(timestr[:dotidx]) ! let msec = str2nr(timestr[dotidx + 1:]) ! return (sec * 1000) + (msec / 1000) endfunc func! s:assert_takes_longer(cmd, time_ms) --- 1,7 ---- " Test for sleep and sleep! commands func! s:get_time_ms() ! return float2nr(reltimefloat(reltime()) * 1000) endfunc func! s:assert_takes_longer(cmd, time_ms) *** ../vim-9.0.1410/src/version.c 2023-03-16 21:01:16.333965399 +0000 --- src/version.c 2023-03-16 21:35:32.099537551 +0000 *************** *** 697,698 **** --- 697,700 ---- { /* Add new patch number below this line */ + /**/ + 1411, /**/ -- Microsoft: "Windows NT 4.0 now has the same user-interface as Windows 95" Windows 95: "Press CTRL-ALT-DEL to reboot" Windows NT 4.0: "Press CTRL-ALT-DEL to login" /// Bram Moolenaar -- Bram@Moolenaar.net -- http://www.Moolenaar.net \\\ /// \\\ \\\ sponsor Vim, vote for features -- http://www.Vim.org/sponsor/ /// \\\ help me help AIDS victims -- http://ICCF-Holland.org ///