void w_perf_log(w_perf_t *perf) {
json_t *info;
char *dumped = NULL;
if (!perf->will_log) {
return;
}
// Assemble a perf blob
info = json_pack("{s:u, s:O, s:i, s:u}", //
"description", perf->description, //
"meta", perf->meta_data, //
"pid", getpid(), //
"version", PACKAGE_VERSION //
);
#ifdef WATCHMAN_BUILD_INFO
set_unicode_prop(info, "buildinfo", WATCHMAN_BUILD_INFO);
#endif
#define ADDTV(name, tv) \
set_prop(info, name, json_real(w_timeval_abs_seconds(tv)))
ADDTV("elapsed_time", perf->duration);
ADDTV("start_time", perf->time_begin);
#ifdef HAVE_SYS_RESOURCE_H
ADDTV("user_time", perf->usage.ru_utime);
ADDTV("system_time", perf->usage.ru_stime);
#define ADDU(n) set_prop(info, #n, json_integer(perf->usage.n))
ADDU(ru_maxrss);
ADDU(ru_ixrss);
ADDU(ru_idrss);
ADDU(ru_minflt);
ADDU(ru_majflt);
ADDU(ru_nswap);
ADDU(ru_inblock);
ADDU(ru_oublock);
ADDU(ru_msgsnd);
ADDU(ru_msgrcv);
ADDU(ru_nsignals);
ADDU(ru_nvcsw);
ADDU(ru_nivcsw);
#endif // HAVE_SYS_RESOURCE_H
#undef ADDU
#undef ADDTV
// Log to the log file
dumped = json_dumps(info, 0);
w_log(W_LOG_ERR, "PERF: %s\n", dumped);
free(dumped);
if (!cfg_get_json(NULL, "perf_logger_command")) {
json_decref(info);
return;
}
// Send this to our logging thread for async processing
pthread_mutex_lock(&perf_log_lock);
if (!perf_log_thread_started) {
pthread_cond_init(&perf_log_cond, NULL);
pthread_create(&perf_log_thr, NULL, perf_log_thread, NULL);
perf_log_thread_started = true;
}
if (!perf_log_samples) {
perf_log_samples = json_array();
}
json_array_append_new(perf_log_samples, info);
pthread_mutex_unlock(&perf_log_lock);
pthread_cond_signal(&perf_log_cond);
}
/* Process 3OP Integer instructions */
bool eval_3OP_Int(struct lilith* vm, struct Instruction* c)
{
#ifdef DEBUG
char Name[20] = "ILLEGAL_3OP";
#endif
switch(c->raw_XOP)
{
case 0x000: /* ADD */
{
#ifdef DEBUG
strncpy(Name, "ADD", 19);
#elif TRACE
record_trace("ADD");
#endif
ADD(vm, c);
break;
}
case 0x001: /* ADDU */
{
#ifdef DEBUG
strncpy(Name, "ADDU", 19);
#elif TRACE
record_trace("ADDU");
#endif
ADDU(vm, c);
break;
}
case 0x002: /* SUB */
{
#ifdef DEBUG
strncpy(Name, "SUB", 19);
#elif TRACE
record_trace("SUB");
#endif
SUB(vm, c);
break;
}
case 0x003: /* SUBU */
{
#ifdef DEBUG
strncpy(Name, "SUBU", 19);
#elif TRACE
record_trace("SUBU");
#endif
SUBU(vm, c);
break;
}
case 0x004: /* CMP */
{
#ifdef DEBUG
strncpy(Name, "CMP", 19);
#elif TRACE
record_trace("CMP");
#endif
CMP(vm, c);
break;
}
case 0x005: /* CMPU */
{
#ifdef DEBUG
strncpy(Name, "CMPU", 19);
#elif TRACE
record_trace("CMPU");
#endif
CMPU(vm, c);
break;
}
case 0x006: /* MUL */
{
#ifdef DEBUG
strncpy(Name, "MUL", 19);
#elif TRACE
record_trace("MUL");
#endif
MUL(vm, c);
break;
}
case 0x007: /* MULH */
{
#ifdef DEBUG
strncpy(Name, "MULH", 19);
#elif TRACE
record_trace("MULH");
#endif
MULH(vm, c);
break;
}
case 0x008: /* MULU */
{
#ifdef DEBUG
strncpy(Name, "MULU", 19);
#elif TRACE
record_trace("MULU");
#endif
MULU(vm, c);
break;
}
case 0x009: /* MULUH */
{
#ifdef DEBUG
strncpy(Name, "MULUH", 19);
#elif TRACE
record_trace("MULUH");
#endif
MULUH(vm, c);
break;
}
case 0x00A: /* DIV */
{
#ifdef DEBUG
strncpy(Name, "DIV", 19);
#elif TRACE
record_trace("DIV");
#endif
DIV(vm, c);
break;
}
case 0x00B: /* MOD */
{
#ifdef DEBUG
strncpy(Name, "MOD", 19);
#elif TRACE
record_trace("MOD");
#endif
MOD(vm, c);
break;
}
case 0x00C: /* DIVU */
{
#ifdef DEBUG
strncpy(Name, "DIVU", 19);
#elif TRACE
record_trace("DIVU");
#endif
DIVU(vm, c);
break;
}
case 0x00D: /* MODU */
{
#ifdef DEBUG
strncpy(Name, "MODU", 19);
#elif TRACE
record_trace("MODU");
#endif
MODU(vm, c);
break;
}
case 0x010: /* MAX */
{
#ifdef DEBUG
strncpy(Name, "MAX", 19);
#elif TRACE
record_trace("MAX");
#endif
MAX(vm, c);
break;
}
case 0x011: /* MAXU */
{
#ifdef DEBUG
strncpy(Name, "MAXU", 19);
#elif TRACE
record_trace("MAXU");
#endif
MAXU(vm, c);
break;
}
case 0x012: /* MIN */
{
#ifdef DEBUG
strncpy(Name, "MIN", 19);
#elif TRACE
record_trace("MIN");
#endif
MIN(vm, c);
break;
}
case 0x013: /* MINU */
{
#ifdef DEBUG
strncpy(Name, "MINU", 19);
#elif TRACE
record_trace("MINU");
#endif
MINU(vm, c);
break;
}
case 0x014: /* PACK */
case 0x015: /* UNPACK */
case 0x016: /* PACK8.CO */
case 0x017: /* PACK8U.CO */
case 0x018: /* PACK16.CO */
case 0x019: /* PACK16U.CO */
case 0x01A: /* PACK32.CO */
case 0x01B: /* PACK32U.CO */
{
illegal_instruction(vm, c);
break;
}
case 0x020: /* AND */
{
#ifdef DEBUG
strncpy(Name, "AND", 19);
#elif TRACE
record_trace("AND");
#endif
AND(vm, c);
break;
}
case 0x021: /* OR */
{
#ifdef DEBUG
strncpy(Name, "OR", 19);
#elif TRACE
record_trace("OR");
#endif
OR(vm, c);
break;
}
case 0x022: /* XOR */
{
#ifdef DEBUG
strncpy(Name, "XOR", 19);
#elif TRACE
record_trace("XOR");
#endif
XOR(vm, c);
break;
}
case 0x023: /* NAND */
{
#ifdef DEBUG
strncpy(Name, "NAND", 19);
#elif TRACE
record_trace("NAND");
#endif
NAND(vm, c);
break;
}
case 0x024: /* NOR */
{
#ifdef DEBUG
strncpy(Name, "NOR", 19);
#elif TRACE
record_trace("NOR");
#endif
NOR(vm, c);
break;
}
case 0x025: /* XNOR */
{
#ifdef DEBUG
strncpy(Name, "XNOR", 19);
#elif TRACE
record_trace("XNOR");
#endif
XNOR(vm, c);
break;
}
case 0x026: /* MPQ */
{
#ifdef DEBUG
strncpy(Name, "MPQ", 19);
#elif TRACE
record_trace("MPQ");
#endif
MPQ(vm, c);
break;
}
case 0x027: /* LPQ */
{
#ifdef DEBUG
strncpy(Name, "LPQ", 19);
#elif TRACE
record_trace("LPQ");
#endif
LPQ(vm, c);
break;
}
case 0x028: /* CPQ */
{
#ifdef DEBUG
strncpy(Name, "CPQ", 19);
#elif TRACE
record_trace("CPQ");
#endif
CPQ(vm, c);
break;
}
case 0x029: /* BPQ */
{
#ifdef DEBUG
strncpy(Name, "BPQ", 19);
#elif TRACE
record_trace("BPQ");
#endif
BPQ(vm, c);
break;
}
case 0x030: /* SAL */
{
#ifdef DEBUG
strncpy(Name, "SAL", 19);
#elif TRACE
record_trace("SAL");
#endif
SAL(vm, c);
break;
}
case 0x031: /* SAR */
{
#ifdef DEBUG
strncpy(Name, "SAR", 19);
#elif TRACE
record_trace("SAR");
#endif
SAR(vm, c);
break;
}
case 0x032: /* SL0 */
{
#ifdef DEBUG
strncpy(Name, "SL0", 19);
#elif TRACE
record_trace("SL0");
#endif
SL0(vm, c);
break;
}
case 0x033: /* SR0 */
{
#ifdef DEBUG
strncpy(Name, "SR0", 19);
#elif TRACE
record_trace("SR0");
#endif
SR0(vm, c);
break;
}
case 0x034: /* SL1 */
{
#ifdef DEBUG
strncpy(Name, "SL1", 19);
#elif TRACE
record_trace("SL1");
#endif
SL1(vm, c);
break;
}
case 0x035: /* SR1 */
{
#ifdef DEBUG
strncpy(Name, "SR1", 19);
#elif TRACE
record_trace("SR1");
#endif
SR1(vm, c);
break;
}
case 0x036: /* ROL */
{
#ifdef DEBUG
strncpy(Name, "ROL", 19);
#elif TRACE
record_trace("ROL");
#endif
ROL(vm, c);
break;
}
case 0x037: /* ROR */
{
#ifdef DEBUG
strncpy(Name, "ROR", 19);
#elif TRACE
record_trace("ROR");
#endif
ROR(vm, c);
break;
}
case 0x038: /* LOADX */
{
#ifdef DEBUG
strncpy(Name, "LOADX", 19);
#elif TRACE
record_trace("LOADX");
#endif
LOADX(vm, c);
break;
}
case 0x039: /* LOADX8 */
{
#ifdef DEBUG
strncpy(Name, "LOADX8", 19);
#elif TRACE
record_trace("LOADX8");
#endif
LOADX8(vm, c);
break;
}
case 0x03A: /* LOADXU8 */
{
#ifdef DEBUG
strncpy(Name, "LOADXU8", 19);
#elif TRACE
record_trace("LOADXU8");
#endif
LOADXU8(vm, c);
break;
}
case 0x03B: /* LOADX16 */
{
#ifdef DEBUG
strncpy(Name, "LOADX16", 19);
#elif TRACE
record_trace("LOADX16");
#endif
LOADX16(vm, c);
break;
}
case 0x03C: /* LOADXU16 */
{
#ifdef DEBUG
strncpy(Name, "LOADXU16", 19);
#elif TRACE
record_trace("LOADXU16");
#endif
LOADXU16(vm, c);
break;
}
case 0x03D: /* LOADX32 */
{
#ifdef DEBUG
strncpy(Name, "LOADX32", 19);
#elif TRACE
record_trace("LOADX32");
#endif
LOADX32(vm, c);
break;
}
case 0x03E: /* LOADXU32 */
{
#ifdef DEBUG
strncpy(Name, "LOADXU32", 19);
#elif TRACE
record_trace("LOADXU32");
#endif
LOADXU32(vm, c);
break;
}
case 0x048: /* STOREX */
{
#ifdef DEBUG
strncpy(Name, "STOREX", 19);
#elif TRACE
record_trace("STOREX");
#endif
STOREX(vm, c);
break;
}
case 0x049: /* STOREX8 */
{
#ifdef DEBUG
strncpy(Name, "STOREX8", 19);
#elif TRACE
record_trace("STOREX8");
#endif
STOREX8(vm, c);
break;
}
case 0x04A: /* STOREX16 */
{
#ifdef DEBUG
strncpy(Name, "STOREX16", 19);
#elif TRACE
record_trace("STOREX16");
#endif
STOREX16(vm, c);
break;
}
case 0x04B: /* STOREX32 */
{
#ifdef DEBUG
strncpy(Name, "STOREX32", 19);
#elif TRACE
record_trace("STOREX32");
#endif
STOREX32(vm, c);
break;
}
case 0x050: /* CMPJUMP.G */
{
#ifdef DEBUG
strncpy(Name, "CMPJUMP.G", 19);
#elif TRACE
record_trace("CMPJUMP.G");
#endif
CMPJUMP_G(vm, c);
break;
}
case 0x051: /* CMPJUMP.GE */
{
#ifdef DEBUG
strncpy(Name, "CMPJUMP.GE", 19);
#elif TRACE
record_trace("CMPJUMP.GE");
#endif
CMPJUMP_GE(vm, c);
break;
}
case 0x052: /* CMPJUMP.E */
{
#ifdef DEBUG
strncpy(Name, "CMPJUMP.E", 19);
#elif TRACE
record_trace("CMPJUMP.E");
#endif
CMPJUMP_E(vm, c);
break;
}
case 0x053: /* CMPJUMP.NE */
{
#ifdef DEBUG
strncpy(Name, "CMPJUMP.NE", 19);
#elif TRACE
record_trace("CMPJUMP.NE");
#endif
CMPJUMP_NE(vm, c);
break;
}
case 0x054: /* CMPJUMP.LE */
{
#ifdef DEBUG
strncpy(Name, "CMPJUMP.LE", 19);
#elif TRACE
record_trace("CMPJUMP.LE");
#endif
CMPJUMP_LE(vm, c);
break;
}
case 0x055: /* CMPJUMP.L */
{
#ifdef DEBUG
strncpy(Name, "CMPJUMP.L", 19);
#elif TRACE
record_trace("CMPJUMP.L");
#endif
CMPJUMP_L(vm, c);
break;
}
case 0x060: /* CMPJUMPU.G */
{
#ifdef DEBUG
strncpy(Name, "CMPJUMPU.G", 19);
#elif TRACE
record_trace("CMPJUMPU.G");
#endif
CMPJUMPU_G(vm, c);
break;
}
case 0x061: /* CMPJUMPU.GE */
{
#ifdef DEBUG
strncpy(Name, "CMPJUMPU.GE", 19);
#elif TRACE
record_trace("CMPJUMPU.GE");
#endif
CMPJUMPU_GE(vm, c);
break;
}
case 0x064: /* CMPJUMPU.LE */
{
#ifdef DEBUG
strncpy(Name, "CMPJUMPU.LE", 19);
#elif TRACE
record_trace("CMPJUMPU.LE");
#endif
CMPJUMPU_LE(vm, c);
break;
}
case 0x065: /* CMPJUMPU.L */
{
#ifdef DEBUG
strncpy(Name, "CMPJUMPU.L", 19);
#elif TRACE
record_trace("CMPJUMPU.L");
#endif
CMPJUMPU_L(vm, c);
break;
}
default:
{
illegal_instruction(vm, c);
break;
}
}
#ifdef DEBUG
fprintf(stdout, "# %s reg%u reg%u reg%u\n", Name, c->reg0, c->reg1, c->reg2);
#endif
return false;
}
void watchman_perf_sample::log() {
char *dumped = NULL;
if (!will_log) {
return;
}
// Assemble a perf blob
auto info = json_object(
{{"description", typed_string_to_json(description)},
{"meta", meta_data},
{"pid", json_integer(getpid())},
{"version", typed_string_to_json(PACKAGE_VERSION, W_STRING_UNICODE)}});
#ifdef WATCHMAN_BUILD_INFO
info.set(
"buildinfo", typed_string_to_json(WATCHMAN_BUILD_INFO, W_STRING_UNICODE));
#endif
#define ADDTV(name, tv) info.set(name, json_real(w_timeval_abs_seconds(tv)))
ADDTV("elapsed_time", duration);
ADDTV("start_time", time_begin);
#ifdef HAVE_SYS_RESOURCE_H
ADDTV("user_time", usage.ru_utime);
ADDTV("system_time", usage.ru_stime);
#define ADDU(n) info.set(#n, json_integer(usage.n))
ADDU(ru_maxrss);
ADDU(ru_ixrss);
ADDU(ru_idrss);
ADDU(ru_minflt);
ADDU(ru_majflt);
ADDU(ru_nswap);
ADDU(ru_inblock);
ADDU(ru_oublock);
ADDU(ru_msgsnd);
ADDU(ru_msgrcv);
ADDU(ru_nsignals);
ADDU(ru_nvcsw);
ADDU(ru_nivcsw);
#endif // HAVE_SYS_RESOURCE_H
#undef ADDU
#undef ADDTV
// Log to the log file
dumped = json_dumps(info, 0);
w_log(W_LOG_ERR, "PERF: %s\n", dumped);
free(dumped);
if (!cfg_get_json("perf_logger_command")) {
return;
}
// Send this to our logging thread for async processing
{
// The common case is that we already set up the logging
// thread and that we can just log through it.
auto rlock = perfThread.rlock();
if (rlock->get()) {
(*rlock)->addSample(std::move(info));
return;
}
}
// If it wasn't set, then we need an exclusive lock to
// make sure that we don't spawn multiple instances.
{
auto wlock = perfThread.wlock();
if (!wlock->get()) {
*wlock = watchman::make_unique<PerfLogThread>();
}
(*wlock)->addSample(std::move(info));
}
}
