[RDY] viml: impl profiling on top of uv_hrtime() #839

aktau · 2014-06-13T14:38:44Z

Should be better than gettimeofday() since libuv uses higher resolution
clocks on most UNIX platforms. Libuv also tries to use monotonic clocks,
kernel bugs notwithstanding.

Necessary for Windows, which doesn't have gettimeofday().

Relevant issue: #831

References for STATIC_ASSERT:

UPDATE: Since we now have a platform abstract uint64_t type (proftime_T) instead of LARGE_INTEGER and struct timeval, I'm thinking of passing by value and perhaps even eliminating some of the one-line functions.

Ping: @justinmk @ZyX-I @equalsraf

ZyX-I · 2014-06-13T16:17:35Z

src/nvim/eval.c

+///            exactly 2 items
+/// @param[out] tm The proftime_T representation of `arg`
+/// @return OK In case of success, FAIL in case of error
+static int list2proftime(typval_T *arg, proftime_T *tm)


I think you need FUNC_ATTR_NONNULL_ALL here because you are not checking for arg and tm being NULL anywhere. Same for f_reltime and f_reltimestr (actually in my opinion every second function needs FUNC_ATTR_NONNULL_ALL something like every fourth FUNC_ATTR_WARN_UNUSED_RESULT). But these are static ones so such change does not contribute much.

aktau · 2014-06-13T16:29:04Z

And this is non-static function so FUNC_ATTR_NONNULL_ALL should make clang static analysis more correct (AFAIR when I checked Vim with clang static analyzer I got lots of false positives regarding the fact that developers did not check for NULL in cases where NULL return is not possible, but do not remember any reports about passing NULL to some external functions). If you started to modify these functions, including adding documentation it would be good to also provide hints for the analyzer. All modified functions in this file need this. I am not sure whether it is correct to add this change to this pull request though.

I don't think it's a good idea to introduce changes to the other functions in this PR, but I can (and will) change the functions I modified in this PR.

At first I thought that what you suggested was strange since obviously vim will never pass NULL values to any f_ function. But now that you say that apparently it suppresses false positives in the static analyzer, that's a good thing. Will add.

ZyX-I · 2014-06-13T16:44:35Z

src/nvim/ex_cmds2.c

@@ -792,15 +783,11 @@ char * profile_msg(proftime_T *tm)
 */
 void profile_setlimit(long msec, proftime_T *tm)


I think it is good idea to get rid of long here: it is guaranteed to have only 32 bits, while we need 64. If it is 32 bit than msec * 1000000L will overflow if you set timeout in search() to slightly more then 2 seconds.

It will be 32-bit on windows indeed. But I wouldn't change the prototype of the function just yet (a bit more invasive since it's called with long globals and whatnot). How about this:

*tm = uv_hrtime() + ((proftime_T) msec * 1000000ULL);

That should (I think) make it not overflow unless for extremely high values.

ZyX-I · 2014-06-13T17:07:20Z

FUNC_ATTR_NONNULL_ALL should not suppress any false positives, it should make analyzer check that argument cannot be NULL. FUNC_ATTR_NONNULL_RETURN is what should suppress false positives, though you do not need this anywhere in this PR.

ZyX-I · 2014-06-13T17:09:37Z

Neither is particularly useful for static functions (analyzer can simply enter these functions and find out that NULL pointer is dereferenced inside or that function cannot return NULL because it uses malloc function with NONNULL_RETURN), but analyzer does not enter functions in other files (at least it was not last time I checked) so all non-static functions should have any applicable attribute.

aktau · 2014-06-13T17:57:29Z

@ZyX-I I incorporated my version of the msec overflow you pointed out in profile_setlimit, if that's not satisfactory, please say so ;).

I still believe we don't need to check for overflow though, as unsigned overflow is defined and relative intervals are not affected by overflow (unless the interval spans more than the maximum width of the type, which is unlikely).

justinmk · 2014-06-13T18:00:41Z

I'm still debating about removing it (the function) and putting uv_hrtime behind os_hrtime and just calling it directly. What do you think?

You mean remove profile_start? If I'm not mistaken it is the interface for the :profile start VimL command. Also the calls to profile_* in eval.c, etc, at least make the code easier to follow.

But I also I think we should have a os_hrtime function, rather than including uv.h directly in modules outside of os/.

ZyX-I · 2014-06-13T18:34:10Z

src/nvim/eval.c

@@ -12242,7 +12266,7 @@ static void f_round(typval_T *argvars, typval_T *rettv)

  rettv->v_type = VAR_FLOAT;
  if (get_float_arg(argvars, &f) == OK)
-    rettv->vval.v_float = vim_round(f);
+    rettv->vval.v_float = round(f);


Just mentioned: should not the removal of vim_round be the other pull request? I cannot say I am perfect in this matter, but removing vim_round seems completely irrelevant.

ZyX-I · 2014-06-13T18:38:01Z

LGTM now, except for vim_round.

I also think @justinmk complaint is fair, but I cannot say I was thinking using uv_hrtime directly is not good before this complaint.

aktau · 2014-06-14T16:55:16Z

LGTM now, except for vim_round.

I'll pick off the vim_round commit then, and hopefully won't forget it for another PR ;).

aktau · 2014-06-15T17:15:10Z

@ZyX-I @justinmk I've put uv_hrtime behind os_hrtime. I've also added another commit which converts the profiling functions to use by-value parameters instead of pointers. Sadly this change is a bit large because the profiling functions were used in quite a few places.

@ZyX-I I've also added some code which I believe guards better against overflow:

https://github.com/aktau/neovim/blob/b3ce4bdf623c0baa5aac48a2076c61770c958696/src/nvim/ex_cmds2.c#L796-L812 (this used to be now > tm, I believe.
there was something else but I forgot...

Let me know what you think.

@justinmk you provided some profile output earlier. I think it might be a good idea to compare the before-and-after effects of these commits. Can you post a little snippet (or try it out yourself, whatever suits), to make sure I didn't make any mistakes in that department.

felipecrv · 2014-06-16T05:22:25Z

src/nvim/macros.h

+      { enum { ASSERT_CONCAT(assert_line_, __LINE__) = 1/(!!(e)) }; }
+  #endif
+#endif
+


macros.h, misc.h, structs.h... are really bad file names as they become huge and confusing. Please create an assert.h (or something like it) to place the ASSERT_* macros in it from the beginning.

aktau · 2014-06-16T08:21:10Z

macros.h, misc.h, structs.h... are really bad file names as they become huge and confusing. Please create an assert.h (or something like it) to place the ASSERT_* macros in it from the beginning.

@philix since you were the only one that has commented on the new changes and the STATIC_ASSERT macro was the first commit in the list, I thought it cleaner to rebase and force-push.

aktau · 2014-06-16T10:13:28Z

By the way, I just did two profiling runs, one on vanilla vim installed by homebrew (7.4.273), and one on this branch (which should be using uv_hrtime). I posted the result in a gist: https://gist.github.com/aktau/397533f03ea3bff77b19

The format looks good enough so at least I didn't mess that up. If someone wants to check if the numbers add up (literally), feel free :).

UDPDATE: there are some (expected) differences though:

:echom reltimestr(reltime()) . ' - ' . reltimestr(reltime())
" vim: 1402915103.140406 - 1402915103.140426
" nvim: 1406625.804966 - 1406625.804986

As expected, regular vim returns the seconds (and microseconds) since the UNIX epoch, and neovim... something different. What I find strange is that the first 3 digits indicate that there is some sort of relationship between the two.

ZyX-I · 2014-06-16T16:45:48Z

@aktau AFAIR last time I tested uv_hrtime (actually pyuv.util.hrtime()) returned uptime. Now (after hibernate+resume) retested: they are very different.

Vim help says that it returns “the current time”, but unlike vim help for localtime() it does not say anything more specific then “the current time”.

aktau · 2014-06-16T16:59:52Z

@aktau AFAIR last time I tested uv_hrtime (actually pyuv.util.hrtime()) returned uptime. Now (after hibernate+resume) retested: they are very different.

Which system did you test this on? Because on OSX it's actually something "close to" nanoseconds since the UNIX epoch.

Anyway, from inspecting the source it's going to be quite different for every system. I checked getting pure mach_absolute_time() to be sure and if I interpreted it as a UNIX time (first divided by 1000), it was somewhere in august.

So, nothing to worry about I guess, unless someone is relying on reltimestr(reltime())[0] to be seconds since the UNIX epoch. Do you think many people do that?

On Windows, the behaviour should be the same on this branch as it is on vanilla vim (QueryPerformanceCounter).

justinmk · 2014-06-16T17:42:41Z

unless someone is relying on reltimestr(reltime())[0] to be seconds since the UNIX epoch. Do you think many people do that?

Let's just note it on the wiki: https://github.com/neovim/neovim/wiki/Differences-from-vim

As long as we keep track of these differences it's very manageable to check the "list of differences" in the unlikely event that someone reports a bug regarding this.

ZyX-I · 2014-06-17T04:08:28Z

So, nothing to worry about I guess, unless someone is relying on reltimestr(reltime())[0] to be seconds since the UNIX epoch. Do you think many people do that?

There is localtime(). Besides nobody said that “current time” is (not) time since UNIX epoch. And in any case this is what I see on wine when I type :echo localtime() reltime() in vanilla vim:

. You see: [249, -{big number}] which is very different from localtime().

aktau · 2014-06-17T08:45:26Z

You see: [249, -{big number}] which is very different from localtime().

Indeed, as one would expect from looking at the vanilla vim code, it's the low and high DWORD of the QueryPerformanceCounter output.

Let's just note it on the wiki: https://github.com/neovim/neovim/wiki/Differences-from-vim

Agreed.

Do my overflow countermeasures look sufficient to you guys?

felipecrv · 2014-06-18T00:16:14Z

src/nvim/assert.h

@@ -0,0 +1,78 @@
+#ifndef NVIM_ASSERT_H
+#define NVIM_ASSERT_H


equalsraf · 2014-06-23T23:03:10Z

Shouldn't the include for sys/time.h be removed from os/time.c - or at least guarded with HAVE_SYS_TIME_H? At least in Linux it seems the include can be removed.

aktau · 2014-06-24T08:29:40Z

@equalsraf in time it has to either be removed or #ifdef'ed I think, since windows doesn't support it. For now it seems necessary for gettimeofday.

That's something for another PR, but what do you guys think of this gettimeofday emulator? http://social.msdn.microsoft.com/Forums/vstudio/en-US/430449b3-f6dd-4e18-84de-eebd26a8d668/gettimeofday?forum=vcgeneral

equalsraf · 2014-07-01T13:07:16Z

@aktau I'm wondering if we can stop using gettimeofday entirely. Currently gettimeofday is used in the following locations

in term.c to measure click interval (tz is NULL, uses tv_sec and tv_usec)
main.c to measure time difference (tz is NULL, uses tv_sec and tv_usec)
in sha256.c:sha2_seed() to seed rand (tz is NULL, uses tv_sec and tv_usec) but I don't think sha2_seed is ever used in Neovim
os/time.c:os_get_localtime(tz is NULL) to get time

Assuming the first two can use os_hrtime() instead and the third can be removed. The fourth case can be replaced by time() since it only uses second precision anyway.

aktau · 2014-07-01T13:27:23Z

@equalsraf, indeed. Anywhere there is a time interval measurement, we can use a difference between os_hrtime() just fine. Taking into account that it returns nanoseconds. I support this change as it makes everything more cross-platform compatible and we rely on less functions.

About the sha2_seed I'm not sure, if it was only used by the crypto code we may remove it. @schmee will be able to provide input on that.

os/time.c:os_get_localtime(tz is NULL) to get time

That one is for @philix. What you say makes sense though.

aktau · 2014-07-03T12:31:49Z

How do you guys feel about perhaps extracting the functions to profile.c? It would be small, tiny even, but placing it in ex_cmds2.c (whete it was) seems even a tad bit more nonsensical.

ZyX-I · 2014-07-03T14:50:49Z

@aktau It makes sense. I cannot pretend I know why things contained in ex_cmds2 are contained there.

Will be properly solved by PR neovim#839. If that's merged, this commit can be removed.

equalsraf · 2014-07-15T12:18:24Z

ping, it seems this needs to be rebased

aktau · 2014-07-15T19:54:12Z

ping, it seems this needs to be rebased

Rebased and unit tests added. (though I really shouldn't be the one to write all these unit tests, since I implemented them I'm the one most likely to do the tests wrong). But a little sanity checking never hurt anybody.

aktau · 2014-07-15T20:14:21Z

@Hinidu it seems -Wstrict-prototypes caught another function call that I was passing arguments but didn't really take any. I hesitate to call it a bug because it probably wasn't a bug, but I'm glad it was caught ;).

aktau · 2014-07-15T20:53:17Z

Ugh, it appears os.clock() doesn't work very well on linux (a bit strange seeing as how the implementation just calls clock() from time.h). A bit tired of this commit so I changed it with another test that doesn't use os.clock().

aktau · 2014-07-15T21:07:55Z

@tarruda the python client is failing again: https://travis-ci.org/neovim/neovim/jobs/30018551

edit: damn, I didn't know that retriggering the build would erase the log.

justinmk · 2014-07-15T21:18:36Z

src/nvim/os/time.c

@@ -22,6 +22,15 @@ void time_init(void)
  uv_cond_init(&delay_cond);
 }

+/// Obtain a high-resolution timer value


should this be "time" instead of "timer"?

Both sound decent enough to me, timer value implies a little bit more that it can't be used as an actual time, to me. (more like a relative time from an earlier call). What do you think?

"timer" to me implies a timer object with a callback. Just checking if it was intentional.

"timer" standalone sounds the same to me, but "timer value" sounds like something that comes out of a timer, and implies "relativity" to me. That's why I chose it. But it makes no big difference to me, to be honest.

aktau · 2014-07-15T21:29:53Z

Whew, it finally passed. I propose that this get merged so @equalsraf can take it out of his patchset.

justinmk · 2014-07-15T21:40:59Z

I'll look at this tonight, but I hope at least one other person can look at it.

aktau · 2014-07-15T21:43:53Z

I'll look at this tonight, but I hope at least one other person can look at it.

It seems @ZyX-I, @philix and @equalsraf already looked at early versions of this patch (before the squash and extraction to profile.c. Perhaps one of them could sound off and see if it's still to their liking.

aktau · 2014-07-16T14:46:23Z

@oni-link pushed some fixes. If you approve of them I'll squash them in.

oni-link · 2014-07-16T15:07:12Z

@aktau, fixes LGTM.

Can be quite handy, attempt to provide fallbacks for compilers that don't support _Static_assert (which is technically a C11 feature). Suppress warnings as best we can (Clang and GCC warn that we're using a C11 feature while in C99 mode). Needs to be tested for MSVC still.

Just an alias to uv_hrtime. Provides a high-resolution timer.

Should be better than gettimeofday() since libuv uses higher resolution clocks on most UNIX platforms. Libuv also tries to use monotonic clocks, kernel bugs notwithstanding, which is another win over gettimeofday(). Necessary for Windows, which doesn't have gettimeofday(). In vanilla vim, Windows uses QueryPerformanceCounter, which is the correct primitive for this sort of things, but that was removed when slimming up the codebase. Libuv uses QueryPerformanceCounter to implement uv_hrtime() on Windows so the behaviour of vim profiling on Windows should now be the same. The behaviour on Linux should be different (better) though, libuv uses more accurate primitives than gettimeofday(). Other misc. changes: - Added function attributes where relevant (const, pure, ...) - Convert functions to receive scalars: Now that proftime_T is always a (uint64_t) scalar (and not a struct), it's clearer to convert the functions to receive it as such instead of a pointer to a scalar. - Extract profiling funcs to profile.c: make everything clearer and reduces the size of the "catch-all" ex_cmds2.c - Add profile.{c,h} to clint and -Wconv: - Don't use sprintf, use snprintf - Don't use long, use int16_t/int32_t/...

It wasn't used anywhere else, our coding guidelines mandate the tightest scope possible.

Some functions are missing: - profile_self - profile_get_wait - profile_set_wait - profile_sub_wait

aktau · 2014-07-16T15:36:14Z

@aktau, fixes LGTM.

Great. I squashed and pushed again. Travis says it's OK too.

viml: impl profiling on top of uv_hrtime()

justinmk · 2014-07-16T19:57:04Z

src/nvim/eval.c

+  }
+
+  // in f_reltime() we split up the 64-bit proftime_T into two 32-bit
+  // values, now we combine them again.


looks like this was done explicitly on line 11671, not in f_reltime()

I'm sorry, I don't understand what you mean... f_reltime splits the uint64_t in two parts and returns it to the vimscript, this is then passed to list2proftime by the vimscripter.

Oh, I didn't follow that. Thanks.

- Include winsock2.h BEFORE windows.h (based on a comment in winsock2.h) - windows.h already provides a macro RGB(), #undef it before its redefined in macros.h - Define workaround for LC_MESSAGES until libintl can be used - MSVC define for __func__ (available in the latest update of VS2015) - SPECIAL_WILDCHAR is left undefined , it is not needed in Windows

ZyX-I reviewed Jun 13, 2014
View reviewed changes

felipecrv reviewed Jun 16, 2014
View reviewed changes

felipecrv reviewed Jun 18, 2014
View reviewed changes

src/nvim/assert.h

@@ -0,0 +1,78 @@

#ifndef NVIM_ASSERT_H

#define NVIM_ASSERT_H

Copy link

Contributor

felipecrv Jun 18, 2014

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍

equalsraf mentioned this pull request Jun 24, 2014

[RFC] / Master issue: Compiling under Windows (VS2013) #696

Closed

12 tasks

aktau mentioned this pull request Jul 3, 2014

[RDY] remove vim_round() in favour of round() #909

Closed

aktau added a commit to aktau/neovim that referenced this pull request Jul 12, 2014

TEMP/profile: move proftime_T to types.h

05f1751

Will be properly solved by PR neovim#839. If that's merged, this commit can be removed.

aktau added a commit to aktau/neovim that referenced this pull request Jul 12, 2014

TEMP/profile: move proftime_T to types.h

ef67ced

Will be properly solved by PR neovim#839. If that's merged, this commit can be removed.

aktau added a commit to aktau/neovim that referenced this pull request Jul 14, 2014

TEMP/profile: move proftime_T to types.h

01ff776

Will be properly solved by PR neovim#839. If that's merged, this commit can be removed.

justinmk reviewed Jul 15, 2014
View reviewed changes

aktau added 5 commits July 16, 2014 17:12

os: implement os_hrtime

f172b19

Just an alias to uv_hrtime. Provides a high-resolution timer.

profiling: move static to function scope

9386f5d

It wasn't used anywhere else, our coding guidelines mandate the tightest scope possible.

profiling: add tests

6d0f941

Some functions are missing: - profile_self - profile_get_wait - profile_set_wait - profile_sub_wait

justinmk added a commit that referenced this pull request Jul 16, 2014

Merge pull request #839 from aktau/platform-abstract-time-fn

0412c17

viml: impl profiling on top of uv_hrtime()

justinmk merged commit 0412c17 into neovim:master Jul 16, 2014

justinmk mentioned this pull request Jul 16, 2014

[RFC] refactor includes + improve testing infrastructure #941

Merged

justinmk reviewed Jul 16, 2014
View reviewed changes

justinmk mentioned this pull request Jul 21, 2014

[RDY] remove gettimeofday() usage #975

Merged

This was referenced Jul 31, 2014

[RFC] August Newsletter neovim/neovim.github.io#58

Merged

Decide what to do with VimL profiling functions #831

Closed

equalsraf mentioned this pull request Dec 30, 2014

API: nvim_get_instance_id #1758

Open

justinmk mentioned this pull request Mar 9, 2016

Provide an API to get current milliseconds #4433

Closed

		@@ -792,15 +783,11 @@ char * profile_msg(proftime_T *tm)
		*/
		void profile_setlimit(long msec, proftime_T *tm)

[RDY] viml: impl profiling on top of uv_hrtime() #839

[RDY] viml: impl profiling on top of uv_hrtime() #839

Conversation

aktau commented Jun 13, 2014

Choose a reason for hiding this comment

aktau commented Jun 13, 2014

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ZyX-I commented Jun 13, 2014

ZyX-I commented Jun 13, 2014

aktau commented Jun 13, 2014

justinmk commented Jun 13, 2014

Choose a reason for hiding this comment

ZyX-I commented Jun 13, 2014

aktau commented Jun 14, 2014

aktau commented Jun 15, 2014

Choose a reason for hiding this comment

Choose a reason for hiding this comment

aktau commented Jun 16, 2014

aktau commented Jun 16, 2014

ZyX-I commented Jun 16, 2014

aktau commented Jun 16, 2014

justinmk commented Jun 16, 2014

ZyX-I commented Jun 17, 2014

aktau commented Jun 17, 2014

Choose a reason for hiding this comment

equalsraf commented Jun 23, 2014

aktau commented Jun 24, 2014

equalsraf commented Jul 1, 2014

aktau commented Jul 1, 2014

aktau commented Jul 3, 2014

ZyX-I commented Jul 3, 2014

equalsraf commented Jul 15, 2014

aktau commented Jul 15, 2014

aktau commented Jul 15, 2014

aktau commented Jul 15, 2014

aktau commented Jul 15, 2014

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

aktau commented Jul 15, 2014

justinmk commented Jul 15, 2014

aktau commented Jul 15, 2014

aktau commented Jul 16, 2014

oni-link commented Jul 16, 2014

aktau commented Jul 16, 2014

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment