[perf] fix some performance issues

pull/1006/head
Timothy Stack 2 years ago
parent 24a56042d0
commit dfaeee7f44

@ -100,6 +100,11 @@
"description": "The name of the timestamp field in the log message pattern",
"type": "string"
},
"time-field": {
"title": "/<format_name>/time-field",
"description": "The name of the time field in the log message pattern. This field should only be specified if the timestamp field only contains a date.",
"type": "string"
},
"body-field": {
"title": "/<format_name>/body-field",
"description": "The name of the body field in the log message pattern",

@ -47,10 +47,7 @@
* an exttm struct to a string using the ftime() method.
*/
struct date_time_scanner {
date_time_scanner()
{
this->clear();
};
date_time_scanner() { this->clear(); }
void clear()
{
@ -58,7 +55,7 @@ struct date_time_scanner {
this->dts_base_tm = exttm{};
this->dts_fmt_lock = -1;
this->dts_fmt_len = -1;
};
}
/**
* Unlock this scanner so that the format is rediscovered.
@ -73,7 +70,7 @@ struct date_time_scanner {
{
this->dts_base_time = base_time;
localtime_r(&base_time, &this->dts_base_tm.et_tm);
};
}
/**
* Convert a timestamp to local time.
@ -122,7 +119,7 @@ struct date_time_scanner {
return true;
}
return false;
};
}
bool convert_to_timeval(const std::string& time_src, struct timeval& tv_out)
{

@ -73,6 +73,9 @@ enum exttm_bits_t {
ETB_YEAR_SET,
ETB_MONTH_SET,
ETB_DAY_SET,
ETB_HOUR_SET,
ETB_MINUTE_SET,
ETB_SECOND_SET,
ETB_MACHINE_ORIENTED,
ETB_EPOCH_TIME,
ETB_MILLIS_SET,
@ -84,6 +87,9 @@ enum exttm_flags_t {
ETF_YEAR_SET = (1UL << ETB_YEAR_SET),
ETF_MONTH_SET = (1UL << ETB_MONTH_SET),
ETF_DAY_SET = (1UL << ETB_DAY_SET),
ETF_HOUR_SET = (1UL << ETB_HOUR_SET),
ETF_MINUTE_SET = (1UL << ETB_MINUTE_SET),
ETF_SECOND_SET = (1UL << ETB_SECOND_SET),
ETF_MACHINE_ORIENTED = (1UL << ETB_MACHINE_ORIENTED),
ETF_EPOCH_TIME = (1UL << ETB_EPOCH_TIME),
ETF_MILLIS_SET = (1UL << ETB_MILLIS_SET),

@ -0,0 +1,56 @@
{
"$schema": "https://lnav.org/schemas/format-v1.schema.json",
"esx_syslog_log": {
"description": "Format file generated from regex101 entry -- https://regex101.com/r/wHXtl4/1",
"regex": {
"std": {
"pattern": "^(?<timestamp>(?:\\S{3,8}\\s+\\d{1,2} \\d{2}:\\d{2}:\\d{2}|\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}(?:\\.\\d{3})?Z))\\s+(?<level>\\w+)\\((?<syslog_pri>\\d+)\\)(?:\\[\\+\\])?(?:(?: (?<log_syslog_tag>(?<log_procname>(?:[^\\[:]+|[^:]+))(?:\\[(?<log_pid>\\d+)\\])?):\\s*(?<body>.*))$|:?(?:(?: ---)? last message repeated \\d+ times?(?: ---)?))"
},
"notime": {
"pattern": "^(?<timestamp>\\d{4}-\\d{2}-\\d{2})\\s+(?<level>\\w+)\\((?<syslog_pri>\\d+)\\)\\s+(?<log_procname>[^\\[]+)\\[(?<log_pid>\\d+)\\]:\\s(?<new_time>\\d{2}:\\d{2}:\\d{2}\\.\\d+)\\s+(?<body>.*)"
}
},
"level": {
"debug": "^Db$",
"info": "^In$",
"notice": "^No$",
"warning": "^Wa$",
"error": "^Er$",
"critical": "^Cr$",
"fatal": "^Al|Em$"
},
"opid-field": "log_syslog_tag",
"time-field": "new_time",
"multiline": false,
"value": {
"body": {
"kind": "string"
},
"log_pid": {
"kind": "string",
"identifier": true
},
"log_procname": {
"kind": "string",
"identifier": true
},
"log_syslog_tag": {
"kind": "string"
},
"syslog_pri": {
"kind": "string"
},
"timestamp": {
"kind": "string"
}
},
"sample": [
{
"line": "2022-06-02T05:34:56.746Z In(14) ConfigStore[1001430703]: Log for ConfigStore version=1.0 build=build-19833347 option=BETA"
},
{
"line": "2022-06-02T05:34:23Z In(14)[+] hostprofile[1001430319]: {'mode': 'Disabled', 'exceptionUsers': []}"
}
]
}
}

@ -11,6 +11,7 @@ FORMAT_FILES = \
$(srcdir)/%reldir%/elb_log.json \
$(srcdir)/%reldir%/engine_log.json \
$(srcdir)/%reldir%/error_log.json \
$(srcdir)/%reldir%/esx_syslog_log.json \
$(srcdir)/%reldir%/fsck_hfs_log.json \
$(srcdir)/%reldir%/glog_log.json \
$(srcdir)/%reldir%/haproxy_log.json \
@ -36,5 +37,6 @@ FORMAT_FILES = \
$(srcdir)/%reldir%/vdsm_log.json \
$(srcdir)/%reldir%/vmk_log.json \
$(srcdir)/%reldir%/vmw_log.json \
$(srcdir)/%reldir%/vmw_wcp_log.json \
$(srcdir)/%reldir%/xmlrpc_log.json \
$()

@ -0,0 +1,40 @@
{
"$schema": "https://lnav.org/schemas/format-v1.schema.json",
"vmw_wcp_log": {
"title": "VMware WCP Log",
"description": "Log files for the Workload Control Plane",
"url": "https://docs.vmware.com/en/VMware-vSphere/7.0/vmware-vsphere-with-tanzu/GUID-2A989D79-463C-4EC8-A5F2-CDC3A2C827FB.html",
"regex": {
"std": {
"pattern": "^(?<timestamp>\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}\\.\\d{3}Z)\\s+(?<level>\\w+)\\s+wcp\\s\\[(?<srcfile>[^:]+):(?<srcline>\\d+)\\](\\s+\\[opID=(?<opid>[^\\]]+)\\])?\\s+(?<body>.*)"
}
},
"opid-field": "opid",
"value": {
"body": {
"kind": "string"
},
"opid": {
"kind": "string"
},
"srcfile": {
"kind": "string",
"identifier": true
},
"srcline": {
"kind": "string",
"identifier": true
}
},
"sample": [
{
"line": "2022-06-02T12:25:11.537Z info wcp [eamagency/util.go:148] [opID=vCLS] Going to read service config",
"level": "info"
},
{
"line": "2022-06-02T10:54:45.001Z debug wcp [auth/session.go:156] Removing expired sessions",
"level": "debug"
}
]
}
}

@ -656,18 +656,17 @@ handle_paging_key(int ch)
case 'p':
if (tc == &lnav_data.ld_views[LNV_LOG]) {
field_overlay_source* fos;
fos = (field_overlay_source*) tc->get_overlay_source();
auto* fos = dynamic_cast<field_overlay_source*>(
tc->get_overlay_source());
fos->fos_contexts.top().c_show
= !fos->fos_contexts.top().c_show;
tc->reload_data();
tc->set_needs_update();
} else if (tc == &lnav_data.ld_views[LNV_DB]) {
db_overlay_source* dos
= (db_overlay_source*) tc->get_overlay_source();
auto* dos = dynamic_cast<db_overlay_source*>(
tc->get_overlay_source());
dos->dos_active = !dos->dos_active;
tc->reload_data();
tc->set_needs_update();
}
break;

@ -797,18 +797,32 @@ external_log_format::scan(logfile& lf,
}
pcre_context::capture_t* ts = pc[fpat->p_timestamp_field_index];
pcre_context::capture_t* time_cap = pc[fpat->p_time_field_index];
pcre_context::capture_t* level_cap = pc[fpat->p_level_field_index];
pcre_context::capture_t* mod_cap = pc[fpat->p_module_field_index];
pcre_context::capture_t* opid_cap = pc[fpat->p_opid_field_index];
pcre_context::capture_t* body_cap = pc[fpat->p_body_field_index];
const char* ts_str = pi.get_substr_start(ts);
auto ts_str_len = ts->length();
const char* last;
struct exttm log_time_tm;
struct timeval log_tv;
uint8_t mod_index = 0, opid = 0;
char combined_datetime_buf[512];
if (time_cap != nullptr) {
ts_str_len = snprintf(combined_datetime_buf,
sizeof(combined_datetime_buf),
"%.*sT%.*s",
ts->length(),
ts_str,
time_cap->length(),
pi.get_substr_start(time_cap));
ts_str = combined_datetime_buf;
}
if ((last = this->lf_date_time.scan(ts_str,
ts->length(),
ts_str_len,
this->get_timestamp_formats(),
&log_time_tm,
log_tv))
@ -816,7 +830,7 @@ external_log_format::scan(logfile& lf,
{
this->lf_date_time.unlock();
if ((last = this->lf_date_time.scan(ts_str,
ts->length(),
ts_str_len,
this->get_timestamp_formats(),
&log_time_tm,
log_tv))
@ -1722,6 +1736,9 @@ external_log_format::build(std::vector<lnav::console::user_message>& errors)
if (name == this->lf_timestamp_field) {
pat.p_timestamp_field_index = name_iter->index();
}
if (name == this->lf_time_field) {
pat.p_time_field_index = name_iter->index();
}
if (name == this->elf_level_field) {
pat.p_level_field_index = name_iter->index();
}

@ -303,6 +303,7 @@ public:
{
this->lf_pattern_locks.clear();
this->lf_date_time.clear();
this->lf_time_scanner.clear();
}
/**
@ -466,8 +467,10 @@ public:
uint8_t lf_mod_index{0};
bool lf_multiline{true};
date_time_scanner lf_date_time;
date_time_scanner lf_time_scanner;
std::vector<pattern_for_lines> lf_pattern_locks;
intern_string_t lf_timestamp_field{intern_string::lookup("timestamp", -1)};
intern_string_t lf_time_field;
std::vector<const char*> lf_timestamp_format;
unsigned int lf_timestamp_flags{0};
std::map<std::string, action_def> lf_action_defs;

@ -103,6 +103,7 @@ public:
std::vector<indexed_value_def> p_value_by_index;
std::vector<int> p_numeric_value_indexes;
int p_timestamp_field_index{-1};
int p_time_field_index{-1};
int p_level_field_index{-1};
int p_module_field_index{-1};
int p_opid_field_index{-1};
@ -131,12 +132,9 @@ public:
jlf_yajl_handle(nullptr, yajl_handle_deleter()), elf_name(name)
{
this->jlf_line_offsets.reserve(128);
};
}
const intern_string_t get_name() const
{
return this->elf_name;
};
const intern_string_t get_name() const { return this->elf_name; }
bool match_name(const std::string& filename);
@ -177,7 +175,7 @@ public:
vd_iter->second->vd_meta.lvm_user_hidden = val;
return true;
};
}
std::shared_ptr<log_format> specialized(int fmt_lock);

@ -797,6 +797,12 @@ struct json_path_container format_handlers = {
.with_description(
"The name of the timestamp field in the log message pattern")
.for_field(&log_format::lf_timestamp_field),
json_path_handler("time-field", read_format_field)
.with_description(
"The name of the time field in the log message pattern. This "
"field should only be specified if the timestamp field only "
"contains a date.")
.for_field(&log_format::lf_time_field),
json_path_handler("body-field", read_format_field)
.with_description(
"The name of the body field in the log message pattern")

@ -203,15 +203,20 @@ logfile::process_prefix(shared_buffer_ref& sbr, const line_info& li)
++iter)
{
if (!(*iter)->match_name(this->lf_filename)) {
log_debug("(%s) does not match file name: %s",
(*iter)->get_name().get(),
this->lf_filename.c_str());
if (li.li_file_range.fr_offset == 0) {
log_debug("(%s) does not match file name: %s",
(*iter)->get_name().get(),
this->lf_filename.c_str());
}
continue;
}
if (!(*iter)->match_mime_type(this->lf_options.loo_file_format)) {
log_debug("(%s) does not match file format: %d",
(*iter)->get_name().get(),
this->lf_options.loo_file_format);
if (li.li_file_range.fr_offset == 0) {
log_debug("(%s) does not match file format: %s",
(*iter)->get_name().get(),
fmt::to_string(this->lf_options.loo_file_format)
.c_str());
}
continue;
}

@ -2165,7 +2165,14 @@ logfile_sub_source::text_crumbs_for_line(int line,
auto msg_line_number = std::distance(msg_start_iter, line_pair.second);
auto line_from_top = line - msg_line_number;
if (sf_lines.size() > 1) {
this->lss_token_meta = lnav::document::discover_structure(sf);
if (this->lss_token_meta_line != file_line_number
|| this->lss_token_meta_size != sf.length())
{
this->lss_token_meta = lnav::document::discover_structure(sf);
this->lss_token_meta_line = file_line_number;
this->lss_token_meta_size = sf.length();
}
const auto initial_size = crumbs.size();
file_off_t line_offset = 0;
file_off_t line_end_offset = sf.length();

@ -960,6 +960,8 @@ private:
std::string lss_token_value;
string_attrs_t lss_token_attrs;
lnav::document::metadata lss_token_meta;
int lss_token_meta_line{-1};
int lss_token_meta_size{0};
std::vector<logline_value> lss_token_values;
int lss_token_shift_start{0};
int lss_token_shift_size{0};

@ -60,32 +60,43 @@ int main(int argc, char *argv[])
fputs(PRELUDE, stdout);
for (int lpc = 1; lpc < argc; lpc++) {
const char *arg = argv[lpc];
const char* arg = argv[lpc];
printf("bool ptime_f%d(struct exttm *dst, const char *str, off_t &off, ssize_t len) {\n"
" // log_debug(\"ptime_f%d\");\n",
lpc, lpc);
printf(
"bool ptime_f%d(struct exttm *dst, const char *str, off_t &off, "
"ssize_t len) {\n"
" dst->et_flags = 0;\n"
" // log_debug(\"ptime_f%d\");\n",
lpc,
lpc);
for (int index = 0; arg[index]; arg++) {
if (arg[index] == '%') {
switch (arg[index + 1]) {
case 'a':
case 'Z':
if (arg[index + 2]) {
printf(" if (!ptime_upto('%s', str, off, len)) return false;\n",
escape_char(arg[index + 2]));
}
else {
printf(" if (!ptime_upto_end(str, off, len)) return false;\n");
}
arg += 1;
break;
case '@':
printf(" if (!ptime_at(dst, str, off, len)) return false;\n");
arg += 1;
break;
default:
printf(" if (!ptime_%c(dst, str, off, len)) return false;\n",
arg[index + 1]);
case 'a':
case 'Z':
if (arg[index + 2]) {
printf(
" if (!ptime_upto('%s', str, off, len)) "
"return false;\n",
escape_char(arg[index + 2]));
} else {
printf(
" if (!ptime_upto_end(str, off, len)) "
"return false;\n");
}
arg += 1;
break;
case '@':
printf(
" if (!ptime_at(dst, str, off, len)) return "
"false;\n");
arg += 1;
break;
default:
printf(
" if (!ptime_%c(dst, str, off, len)) return "
"false;\n",
arg[index + 1]);
arg += 1;
break;
}

@ -287,6 +287,7 @@ ptime_S(struct exttm* dst, const char* str, off_t& off_inout, ssize_t len)
}
dst->et_tm.tm_sec
= (str[off_inout] - '0') * 10 + (str[off_inout + 1] - '0');
dst->et_flags |= ETF_SECOND_SET;
});
return (dst->et_tm.tm_sec >= 0 && dst->et_tm.tm_sec <= 59);
@ -320,8 +321,9 @@ ptime_s(struct exttm* dst, const char* str, off_t& off_inout, ssize_t len)
}
secs2tm(epoch, &dst->et_tm);
dst->et_flags = ETF_DAY_SET | ETF_MONTH_SET | ETF_YEAR_SET
| ETF_MACHINE_ORIENTED | ETF_EPOCH_TIME;
dst->et_flags = ETF_DAY_SET | ETF_MONTH_SET | ETF_YEAR_SET | ETF_HOUR_SET
| ETF_MINUTE_SET | ETF_SECOND_SET | ETF_MACHINE_ORIENTED
| ETF_EPOCH_TIME;
return (epoch > 0);
}
@ -377,8 +379,9 @@ ptime_q(struct exttm* dst, const char* str, off_t& off_inout, ssize_t len)
}
secs2tm(epoch, &dst->et_tm);
dst->et_flags = ETF_DAY_SET | ETF_MONTH_SET | ETF_YEAR_SET
| ETF_MACHINE_ORIENTED | ETF_EPOCH_TIME;
dst->et_flags = ETF_DAY_SET | ETF_MONTH_SET | ETF_YEAR_SET | ETF_HOUR_SET
| ETF_MINUTE_SET | ETF_SECOND_SET | ETF_MACHINE_ORIENTED
| ETF_EPOCH_TIME;
return (epoch > 0);
}
@ -434,6 +437,7 @@ ptime_M(struct exttm* dst, const char* str, off_t& off_inout, ssize_t len)
}
dst->et_tm.tm_min
= (str[off_inout] - '0') * 10 + (str[off_inout + 1] - '0');
dst->et_flags |= ETF_MINUTE_SET;
});
return (dst->et_tm.tm_min >= 0 && dst->et_tm.tm_min <= 59);
@ -455,6 +459,7 @@ ptime_H(struct exttm* dst, const char* str, off_t& off_inout, ssize_t len)
}
dst->et_tm.tm_hour
= (str[off_inout] - '0') * 10 + (str[off_inout + 1] - '0');
dst->et_flags |= ETF_HOUR_SET;
});
return (dst->et_tm.tm_hour >= 0 && dst->et_tm.tm_hour <= 23);
@ -487,8 +492,9 @@ ptime_i(struct exttm* dst, const char* str, off_t& off_inout, ssize_t len)
}
secs2tm(epoch, &dst->et_tm);
dst->et_flags = ETF_DAY_SET | ETF_MONTH_SET | ETF_YEAR_SET
| ETF_MACHINE_ORIENTED | ETF_EPOCH_TIME;
dst->et_flags = ETF_DAY_SET | ETF_MONTH_SET | ETF_YEAR_SET | ETF_HOUR_SET
| ETF_MINUTE_SET | ETF_SECOND_SET | ETF_MACHINE_ORIENTED
| ETF_EPOCH_TIME;
return (epoch_ms > 0);
}
@ -523,8 +529,9 @@ ptime_6(struct exttm* dst, const char* str, off_t& off_inout, ssize_t len)
}
secs2tm(epoch, &dst->et_tm);
dst->et_flags = ETF_DAY_SET | ETF_MONTH_SET | ETF_YEAR_SET
| ETF_MACHINE_ORIENTED | ETF_EPOCH_TIME;
dst->et_flags = ETF_DAY_SET | ETF_MONTH_SET | ETF_YEAR_SET | ETF_HOUR_SET
| ETF_MINUTE_SET | ETF_SECOND_SET | ETF_MACHINE_ORIENTED
| ETF_EPOCH_TIME;
return (epoch_us > 0);
}
@ -552,6 +559,7 @@ ptime_I(struct exttm* dst, const char* str, off_t& off_inout, ssize_t len)
if (dst->et_tm.tm_hour < 1 || dst->et_tm.tm_hour > 12) {
return false;
}
dst->et_flags |= ETF_HOUR_SET;
});
return true;
@ -690,6 +698,7 @@ ptime_k(struct exttm* dst, const char* str, off_t& off_inout, ssize_t len)
if (str[off_inout] >= '0' && str[off_inout] <= '9') {
dst->et_tm.tm_hour *= 10;
dst->et_tm.tm_hour += str[off_inout] - '0';
dst->et_flags |= ETF_HOUR_SET;
off_inout += 1;
}
}
@ -750,6 +759,8 @@ ptime_l(struct exttm* dst, const char* str, off_t& off_inout, ssize_t len)
return true;
}
dst->et_flags |= ETF_HOUR_SET;
off_inout = orig_off;
return false;
}
@ -1070,8 +1081,8 @@ ptime_at(struct exttm* dst, const char* str, off_t& off_inout, ssize_t len)
});
}
dst->et_flags |= ETF_DAY_SET | ETF_MONTH_SET | ETF_YEAR_SET
| ETF_MACHINE_ORIENTED | ETF_EPOCH_TIME;
dst->et_flags |= ETF_DAY_SET | ETF_MONTH_SET | ETF_YEAR_SET | ETF_HOUR_SET
| ETF_MINUTE_SET | ETF_SECOND_SET | ETF_MACHINE_ORIENTED | ETF_EPOCH_TIME;
return true;
}

@ -209,6 +209,13 @@ regex101::import(const std::string& url,
named_iter != regex.named_end();
++named_iter)
{
if (strcmp(named_iter->pnc_name, "level") == 0
|| strcmp(named_iter->pnc_name, "body") == 0)
{
// don't need to add this as a value
continue;
}
value_map.gen(named_iter->pnc_name);
{
yajlpp_map cap_map(gen);

Loading…
Cancel
Save