Merge #962 'Implement startuptime functions on top of profiling functions'

This commit is contained in:
Justin M. Keyes
2014-07-20 18:12:45 -04:00
11 changed files with 151 additions and 172 deletions

View File

@@ -9731,9 +9731,7 @@ static void f_has(typval_T *argvars, typval_T *rettv)
"cmdline_info",
"signs",
"smartindent",
#ifdef STARTUPTIME
"startuptime",
#endif
"statusline",
"spell",
"syntax",

View File

@@ -2261,10 +2261,6 @@ do_source (
void *save_funccalp;
int save_debug_break_level = debug_break_level;
scriptitem_T *si = NULL;
#ifdef STARTUPTIME
struct timeval tv_rel;
struct timeval tv_start;
#endif
proftime_T wait_start;
p = expand_env_save(fname);
@@ -2393,10 +2389,13 @@ do_source (
firstline = p;
}
#ifdef STARTUPTIME
if (time_fd != NULL)
time_push(&tv_rel, &tv_start);
#endif
// start measuring script load time if --startuptime was passed and
// time_fd was successfully opened afterwards.
proftime_T rel_time;
proftime_T start_time;
if (time_fd != NULL) {
time_push(&rel_time, &start_time);
}
if (do_profiling == PROF_YES)
prof_child_enter(&wait_start); /* entering a child now */
@@ -2490,13 +2489,12 @@ do_source (
smsg((char_u *)_("continuing in %s"), sourcing_name);
verbose_leave();
}
#ifdef STARTUPTIME
if (time_fd != NULL) {
vim_snprintf((char *)IObuff, IOSIZE, "sourcing %s", fname);
time_msg((char *)IObuff, &tv_start);
time_pop(&tv_rel);
time_msg((char *)IObuff, &start_time);
time_pop(rel_time);
}
#endif
/*
* After a "finish" in debug mode, need to break at first command of next

View File

@@ -1,6 +1,9 @@
#ifndef NVIM_GARRAY_H
#define NVIM_GARRAY_H
#include <stddef.h> // for size_t
#include "nvim/types.h" // for char_u
#include "nvim/log.h"
/// Structure used for growing arrays.

View File

@@ -10,15 +10,36 @@
#include <stdbool.h>
// EXTERN is only defined in main.c. That's where global variables are
// actually defined and initialized.
#ifndef EXTERN
# define EXTERN extern
# define INIT(x)
#else
# ifndef INIT
# define INIT(x) x
# define DO_INIT
# endif
#endif
#include "nvim/ex_eval.h"
#include "nvim/mbyte.h"
#include "nvim/menu.h"
#include "nvim/syntax_defs.h"
#include "nvim/types.h"
/*
* definition of global variables
*/
#define IOSIZE (1024+1) // file I/O and sprintf buffer size
#define MAX_MCO 6 // maximum value for 'maxcombine'
# define MSG_BUF_LEN 480 // length of buffer for small messages
# define MSG_BUF_CLEN (MSG_BUF_LEN / 6) // cell length (worst case: utf-8
// takes 6 bytes for one cell)
/* Values for "starting" */
#define NO_SCREEN 2 /* no screen updating yet */
#define NO_BUFFERS 1 /* not all buffers loaded yet */
@@ -1186,9 +1207,7 @@ EXTERN char bot_top_msg[] INIT(= N_("search hit BOTTOM, continuing at TOP"));
/* For undo we need to know the lowest time possible. */
EXTERN time_t starttime;
#ifdef STARTUPTIME
EXTERN FILE *time_fd INIT(= NULL); /* where to write startup timing */
#endif
/*
* Some compilers warn for not using a return value, but in some situations we

View File

@@ -116,12 +116,6 @@
# define mch_open_rw(n, f) os_open((n), (f), 0)
#endif
#ifdef STARTUPTIME
# define TIME_MSG(s) { if (time_fd != NULL) time_msg(s, NULL); }
#else
# define TIME_MSG(s)
#endif
# define REPLACE_NORMAL(s) (((s) & REPLACE_FLAG) && !((s) & VREPLACE_FLAG))
# define UTF_COMPOSINGLIKE(p1, p2) utf_composinglike((p1), (p2))

View File

@@ -45,6 +45,7 @@
#include "nvim/option.h"
#include "nvim/os_unix.h"
#include "nvim/path.h"
#include "nvim/profile.h"
#include "nvim/quickfix.h"
#include "nvim/screen.h"
#include "nvim/strings.h"
@@ -710,16 +711,14 @@ main_loop (
do_redraw = FALSE;
#ifdef STARTUPTIME
/* Now that we have drawn the first screen all the startup stuff
* has been done, close any file for startup messages. */
if (time_fd != NULL) {
TIME_MSG("first screen update");
TIME_MSG("--- VIM STARTED ---");
TIME_MSG("--- NVIM STARTED ---");
fclose(time_fd);
time_fd = NULL;
}
#endif
}
/*
@@ -1466,16 +1465,14 @@ static void init_params(mparm_T *paramp, int argc, char **argv)
*/
static void init_startuptime(mparm_T *paramp)
{
#ifdef STARTUPTIME
int i;
for (i = 1; i < paramp->argc; ++i) {
for (int i = 1; i < paramp->argc; i++) {
if (STRICMP(paramp->argv[i], "--startuptime") == 0 && i + 1 < paramp->argc) {
time_fd = mch_fopen(paramp->argv[i + 1], "a");
TIME_MSG("--- VIM STARTING ---");
time_start("--- NVIM STARTING ---");
break;
}
}
#endif
starttime = time(NULL);
}
@@ -2220,9 +2217,7 @@ static void usage(void)
main_msg(_("-s <scriptin>\tRead Normal mode commands from file <scriptin>"));
main_msg(_("-w <scriptout>\tAppend all typed commands to file <scriptout>"));
main_msg(_("-W <scriptout>\tWrite all typed commands to file <scriptout>"));
#ifdef STARTUPTIME
main_msg(_("--startuptime <file>\tWrite startup timing messages to <file>"));
#endif
main_msg(_("-i <viminfo>\t\tUse <viminfo> instead of .viminfo"));
main_msg(_("--api-msgpack-metadata\tDump API metadata information and exit"));
main_msg(_("-h or --help\tPrint Help (this message) and exit"));
@@ -2248,90 +2243,3 @@ static void check_swap_exists_action(void)
#endif
#endif
#if defined(STARTUPTIME) || defined(PROTO)
static struct timeval prev_timeval;
/*
* Save the previous time before doing something that could nest.
* set "*tv_rel" to the time elapsed so far.
*/
void time_push(void *tv_rel, void *tv_start)
{
*((struct timeval *)tv_rel) = prev_timeval;
gettimeofday(&prev_timeval, NULL);
((struct timeval *)tv_rel)->tv_usec = prev_timeval.tv_usec
- ((struct timeval *)tv_rel)->tv_usec;
((struct timeval *)tv_rel)->tv_sec = prev_timeval.tv_sec
- ((struct timeval *)tv_rel)->tv_sec;
if (((struct timeval *)tv_rel)->tv_usec < 0) {
((struct timeval *)tv_rel)->tv_usec += 1000000;
--((struct timeval *)tv_rel)->tv_sec;
}
*(struct timeval *)tv_start = prev_timeval;
}
/*
* Compute the previous time after doing something that could nest.
* Subtract "*tp" from prev_timeval;
* Note: The arguments are (void *) to avoid trouble with systems that don't
* have struct timeval.
*/
void
time_pop (
void *tp /* actually (struct timeval *) */
)
{
prev_timeval.tv_usec -= ((struct timeval *)tp)->tv_usec;
prev_timeval.tv_sec -= ((struct timeval *)tp)->tv_sec;
if (prev_timeval.tv_usec < 0) {
prev_timeval.tv_usec += 1000000;
--prev_timeval.tv_sec;
}
}
static void time_diff(struct timeval *then, struct timeval *now)
{
long usec;
long msec;
usec = now->tv_usec - then->tv_usec;
msec = (now->tv_sec - then->tv_sec) * 1000L + usec / 1000L,
usec = usec % 1000L;
fprintf(time_fd, "%03ld.%03ld", msec, usec >= 0 ? usec : usec + 1000L);
}
void
time_msg (
char *mesg,
void *tv_start /* only for do_source: start time; actually
(struct timeval *) */
)
{
static struct timeval start;
struct timeval now;
if (time_fd != NULL) {
if (strstr(mesg, "STARTING") != NULL) {
gettimeofday(&start, NULL);
prev_timeval = start;
fprintf(time_fd, "\n\ntimes in msec\n");
fprintf(time_fd, " clock self+sourced self: sourced script\n");
fprintf(time_fd, " clock elapsed: other lines\n\n");
}
gettimeofday(&now, NULL);
time_diff(&start, &now);
if (((struct timeval *)tv_start) != NULL) {
fprintf(time_fd, " ");
time_diff(((struct timeval *)tv_start), &now);
}
fprintf(time_fd, " ");
time_diff(&prev_timeval, &now);
prev_timeval = now;
fprintf(time_fd, ": %s\n", mesg);
}
}
#endif

View File

@@ -6,6 +6,8 @@
#include "nvim/os/time.h"
#include "nvim/func_attr.h"
#include "nvim/globals.h" // for the global `time_fd` (startuptime)
#ifdef INCLUDE_GENERATED_DECLARATIONS
# include "profile.c.generated.h"
#endif
@@ -182,3 +184,98 @@ int profile_cmp(proftime_T tm1, proftime_T tm2) FUNC_ATTR_CONST
{
return sgn64((int64_t)(tm2 - tm1));
}
/// globals for use in the startuptime related functionality (time_*).
static proftime_T g_start_time;
static proftime_T g_prev_time;
/// time_push - save the previous time before doing something that could nest
///
/// After calling this function, the static global `g_prev_time` will
/// contain the current time.
///
/// @param[out] rel to the time elapsed so far
/// @param[out] start the current time
void time_push(proftime_T *rel, proftime_T *start)
{
proftime_T now = profile_start();
// subtract the previous time from now, store it in `rel`
*rel = profile_sub(now, g_prev_time);
*start = now;
// reset global `g_prev_time` for the next call
g_prev_time = now;
}
/// time_pop - compute the prev time after doing something that could nest
///
/// Subtracts `tp` from the static global `g_prev_time`.
///
/// @param tp the time to subtract
void time_pop(proftime_T tp)
{
g_prev_time -= tp;
}
/// time_diff - print the difference between `then` and `now`
///
/// the format is "msec.usec".
static void time_diff(proftime_T then, proftime_T now)
{
proftime_T diff = profile_sub(now, then);
fprintf(time_fd, "%07.3lf", (double) diff / 1.0E6);
}
/// time_start - initialize the startuptime code
///
/// Needs to be called once before calling other startuptime code (such as
/// time_{push,pop,msg,...}).
///
/// @param message the message that will be displayed
void time_start(const char *message)
{
if (time_fd == NULL) {
return;
}
// intialize the global variables
g_prev_time = g_start_time = profile_start();
fprintf(time_fd, "\n\ntimes in msec\n");
fprintf(time_fd, " clock self+sourced self: sourced script\n");
fprintf(time_fd, " clock elapsed: other lines\n\n");
time_msg(message, NULL);
}
/// time_msg - print out timing info
///
/// @warning don't forget to call `time_start()` once before calling this.
///
/// @param mesg the message to display next to the timing information
/// @param start only for do_source: start time
void time_msg(const char *mesg, const proftime_T *start)
{
if (time_fd == NULL) {
return;
}
// print out the difference between `start` (init earlier) and `now`
proftime_T now = profile_start();
time_diff(g_start_time, now);
// if `start` was supplied, print the diff between `start` and `now`
if (start != NULL) {
fprintf(time_fd, " ");
time_diff(*start, now);
}
// print the difference between the global `g_prev_time` and `now`
fprintf(time_fd, " ");
time_diff(g_prev_time, now);
// reset `g_prev_time` and print the message
g_prev_time = now;
fprintf(time_fd, ": %s\n", mesg);
}

View File

@@ -6,6 +6,10 @@
typedef uint64_t proftime_T;
#define TIME_MSG(s) do { \
if (time_fd != NULL) time_msg(s, NULL); \
} while (0)
#ifdef INCLUDE_GENERATED_DECLARATIONS
# include "profile.h.generated.h"
#endif

View File

@@ -24,4 +24,13 @@ typedef uintptr_t long_u;
*/
typedef unsigned char char_u;
// The u8char_T can hold one decoded UTF-8 character. We normally use 32
// bits now, since some Asian characters don't fit in 16 bits. u8char_T is
// only used for displaying, it could be 16 bits to save memory.
#ifdef UNICODE16
typedef uint16_t u8char_T;
#else
typedef uint32_t u8char_T;
#endif
#endif /* NVIM_TYPES_H */

View File

@@ -145,11 +145,7 @@ static char *(features[]) = {
"+scrollbind",
"+signs",
"+smartindent",
#ifdef STARTUPTIME
"+startuptime",
#else // ifdef STARTUPTIME
"-startuptime",
#endif // ifdef STARTUPTIME
"+statusline",
"+syntax",
"+tag_binary",

View File

@@ -61,18 +61,6 @@ Error: configure did not run properly.Check auto/config.log.
# define MAX_TYPENR 65535
/*
* The u8char_T can hold one decoded UTF-8 character.
* We normally use 32 bits now, since some Asian characters don't fit in 16
* bits. u8char_T is only used for displaying, it could be 16 bits to save
* memory.
*/
# ifdef UNICODE16
typedef uint16_t u8char_T;
# else
typedef uint32_t u8char_T;
# endif
#include "nvim/keymap.h"
#include "nvim/term_defs.h"
#include "nvim/macros.h"
@@ -258,15 +246,8 @@ enum {
#define LSIZE 512 /* max. size of a line in the tags file */
#define IOSIZE (1024+1) /* file i/o and sprintf buffer size */
#define DIALOG_MSG_SIZE 1000 /* buffer size for dialog_msg() */
# define MSG_BUF_LEN 480 /* length of buffer for small messages */
# define MSG_BUF_CLEN (MSG_BUF_LEN / 6) /* cell length (worst case: utf-8
takes 6 bytes for one cell) */
/*
* Maximum length of key sequence to be mapped.
* Must be able to hold an Amiga resize report.
@@ -392,37 +373,11 @@ enum {
*/
#define vim_iswhite(x) ((x) == ' ' || (x) == '\t')
/*
* EXTERN is only defined in main.c. That's where global variables are
* actually defined and initialized.
*/
#ifndef EXTERN
# define EXTERN extern
# define INIT(x)
#else
# ifndef INIT
# define INIT(x) x
# define DO_INIT
# endif
#endif
# define MAX_MCO 6 /* maximum value for 'maxcombine' */
/* Maximum number of bytes in a multi-byte character. It can be one 32-bit
* character of up to 6 bytes, or one 16-bit character of up to three bytes
* plus six following composing characters of three bytes each. */
# define MB_MAXBYTES 21
#include "nvim/buffer_defs.h" /* buffer and windows */
#include "nvim/ex_cmds_defs.h" /* Ex command defines */
/* This has to go after the include of proto.h, as proto/gui.pro declares
* functions of these names. The declarations would break if the defines had
* been seen at that stage. But it must be before globals.h, where error_ga
@@ -436,11 +391,9 @@ enum {
# define USE_MCH_ERRMSG
#endif
#include "nvim/globals.h" /* global variables and messages */
#include "nvim/buffer_defs.h" /* buffer and windows */
#include "nvim/ex_cmds_defs.h" /* Ex command defines */
# ifdef USE_ICONV
# ifndef EILSEQ