Patch 9.0.1411

[Bram Moolenaar]

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 -- Br...@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 ///

[John Marriott]

On 17-Mar-2023 08:43, Bram Moolenaar wrote:
> 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
>
>

After this patch msys2-64 (clang 15.0.7) gives this warning:
<snip>
clang -c -I. -Iproto -DWIN32 -DWINVER=0x0603 -D_WIN32_WINNT=0x0603
-DHAVE_PATHDEF -DFEAT_NORMAL -DHAVE_STDINT_H -D__USE_MINGW_ANSI_STDIO
-pipe -Wall -O3 -fomit-frame-pointer -fpie -fPIE -DFEAT_GUI_MSWIN
-DFEAT_CLIPBOARD time.c -o gobjx86-64/time.o
time.c:261:17: warning: unused variable 'buf' [-Wunused-variable]
    static char buf[50];
                ^
1 warning generated.
</snip>

The attached patch tries to fix it.

Cheers
John

[Bram Moolenaar]

Thanks. However, it's easier to move the declaration to where "buf" is
used. Might as well move the declaration of "tm" as well, since we now
allow for declarations halfway a code block.

--
They now pass three KNIGHTS impaled to a tree. With their feet off the
ground, with one lance through the lot of them, they are skewered up
like a barbecue.
"Monty Python and the Holy Grail" PYTHON (MONTY) PICTURES LTD