@ -0,0 +1,29 @@ | |||
.eunit | |||
*.o | |||
*.beam | |||
*.plt | |||
erl_crash.dump | |||
.concrete/DEV_MODE | |||
# rebar 2.x | |||
.rebar | |||
rel/example_project | |||
ebin/* | |||
deps | |||
# rebar 3 | |||
.rebar3 | |||
_build/ | |||
_checkouts/ | |||
rebar.lock | |||
# idea | |||
.idea | |||
*.iml | |||
cmake-build* | |||
CMakeLists.txt | |||
# nif compile temp file | |||
*.pdb | |||
*.d | |||
compile_commands.json |
@ -0,0 +1,21 @@ | |||
MIT License | |||
Copyright (c) 2019 AICells | |||
Permission is hereby granted, free of charge, to any person obtaining a copy | |||
of this software and associated documentation files (the "Software"), to deal | |||
in the Software without restriction, including without limitation the rights | |||
to use, copy, modify, merge, publish, distribute, sublicense, and/or sell | |||
copies of the Software, and to permit persons to whom the Software is | |||
furnished to do so, subject to the following conditions: | |||
The above copyright notice and this permission notice shall be included in all | |||
copies or substantial portions of the Software. | |||
THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR | |||
IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, | |||
FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE | |||
AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER | |||
LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, | |||
OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE | |||
SOFTWARE. |
@ -0,0 +1,9 @@ | |||
eTpf | |||
===== | |||
An OTP application | |||
Build | |||
----- | |||
$ rebar3 compile |
@ -0,0 +1,255 @@ | |||
// Copyright (c) 2017-Present Pivotal Software, Inc. All rights reserved. | |||
// | |||
// This package, Looking Glass, is double-licensed under the Mozilla | |||
// Public License 1.1 ("MPL") and the Apache License version 2 | |||
// ("ASL"). For the MPL, please see LICENSE-MPL-RabbitMQ. For the ASL, | |||
// please see LICENSE-APACHE2. | |||
// | |||
// This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY KIND, | |||
// either express or implied. See the LICENSE file for specific language governing | |||
// rights and limitations of this software. | |||
// | |||
// If you have any questions regarding licensing, please contact us at | |||
// info@rabbitmq.com. | |||
#define NIF_FUNCTION_NAME(f) lg_ ## f | |||
#include "nif_helpers.h" | |||
// List of atoms used by this NIF. | |||
// | |||
// @todo We don't use threads so perhaps we should make nif_helpers | |||
// better by splitting concerns into threads/not and have nif_helpers | |||
// decide when to create the _nif_thread_ret atom or not. | |||
#define NIF_ATOMS(A) \ | |||
A(_nif_thread_ret_) \ | |||
A(call) \ | |||
A(closed) \ | |||
A(cpu_timestamp) \ | |||
A(discard) \ | |||
A(exception_from) \ | |||
A(exit) \ | |||
A(extra) \ | |||
A(gc_major_end) \ | |||
A(gc_major_start) \ | |||
A(gc_minor_end) \ | |||
A(gc_minor_start) \ | |||
A(getting_linked) \ | |||
A(getting_unlinked) \ | |||
A(in) \ | |||
A(in_exiting) \ | |||
A(link) \ | |||
A(match_spec_result) \ | |||
A(mode) \ | |||
A(monotonic) \ | |||
A(ok) \ | |||
A(open) \ | |||
A(out) \ | |||
A(out_exited) \ | |||
A(out_exiting) \ | |||
A(percent) \ | |||
A(profile) \ | |||
A(receive) \ | |||
A(register) \ | |||
A(remove) \ | |||
A(return_from) \ | |||
A(return_to) \ | |||
A(scheduler_id) \ | |||
A(send) \ | |||
A(send_to_non_existing_process) \ | |||
A(spawn) \ | |||
A(spawned) \ | |||
A(strict_monotonic) \ | |||
A(timestamp) \ | |||
A(trace) \ | |||
A(trace_status) \ | |||
A(tracers) \ | |||
A(unlink) \ | |||
A(unregister) | |||
NIF_ATOMS(NIF_ATOM_DECL) | |||
// List of functions defined in this NIF. | |||
#define NIF_FUNCTIONS(F) \ | |||
F(enabled, 3) \ | |||
F(enabled_call, 3) \ | |||
F(enabled_procs, 3) \ | |||
F(enabled_running_procs, 3) \ | |||
F(enabled_send, 3) \ | |||
F(trace, 5) | |||
NIF_FUNCTIONS(NIF_FUNCTION_H_DECL) | |||
static int load(ErlNifEnv* env, void** priv_data, ERL_NIF_TERM load_info) | |||
{ | |||
NIF_ATOMS(NIF_ATOM_INIT) | |||
return 0; | |||
} | |||
static int upgrade(ErlNifEnv* env, void** priv_data, void** old_priv_data, ERL_NIF_TERM load_info) | |||
{ | |||
*priv_data = *old_priv_data; | |||
return 0; | |||
} | |||
static void unload(ErlNifEnv* env, void* priv_data) | |||
{ | |||
} | |||
// enabled(TraceTag, TracerState, Tracee) | |||
NIF_FUNCTION(enabled) | |||
{ | |||
ERL_NIF_TERM tracers, value; | |||
ErlNifPid tracer; | |||
// @todo We can go one step further by having the one pid | |||
// in its own value in the map, skipping a get_map_value step. | |||
// This function will only be called for trace_status. | |||
// We can take a few shortcuts knowing this. | |||
// Disable the trace when the tracers option is missing. | |||
if (!enif_get_map_value(env, argv[1], atom_tracers, &tracers)) | |||
return atom_remove; | |||
// Because the tracers supervisor is a one_for_all, we only need | |||
// to check one of the tracer processes to confirm all are alive. | |||
// We know for a fact that this key exists because | |||
// there's at least one tracer process. | |||
enif_get_map_value(env, tracers, enif_make_int(env, 0), &value); | |||
// Disable the trace when one of the tracers is not a local process. | |||
if (!enif_get_local_pid(env, value, &tracer)) | |||
return atom_remove; | |||
// Disable the trace when one of the tracers is not alive. | |||
if (!enif_is_process_alive(env, &tracer)) | |||
return atom_remove; | |||
return atom_discard; | |||
} | |||
NIF_FUNCTION(enabled_call) | |||
{ | |||
// We always want both call and return_to. | |||
return atom_trace; | |||
} | |||
NIF_FUNCTION(enabled_procs) | |||
{ | |||
ERL_NIF_TERM mode; | |||
// We only want the spawn and exit events when 'profile' mode | |||
// is enabled. Technically we only care about exits for callgrind, | |||
// but spawn is cheap to keep and useful for message profilers. | |||
if (enif_get_map_value(env, argv[1], atom_mode, &mode) | |||
&& enif_is_identical(atom_profile, mode) | |||
&& !(enif_is_identical(atom_spawn, argv[0]) | |||
|| enif_is_identical(atom_exit, argv[0]))) { | |||
return atom_discard; | |||
} | |||
return atom_trace; | |||
} | |||
NIF_FUNCTION(enabled_running_procs) | |||
{ | |||
// We always want both in and out. | |||
return atom_trace; | |||
} | |||
NIF_FUNCTION(enabled_send) | |||
{ | |||
// We always want both send and send_to_non_existing_process. | |||
return atom_trace; | |||
} | |||
// trace(TraceTag, TracerState, Tracee, TraceTerm, Opts) | |||
NIF_FUNCTION(trace) | |||
{ | |||
ERL_NIF_TERM tracers, head, ts, extra, mspec, msg; | |||
ErlNifPid tracer; | |||
unsigned int nth; | |||
size_t len; | |||
int has_extra, has_mspec; | |||
if (!enif_get_map_value(env, argv[1], atom_tracers, &tracers)) | |||
return atom_ok; | |||
// We know for a fact that the argument is a map. And if not, | |||
// no problem because we will return when trying to get a value from it. | |||
enif_get_map_size(env, tracers, &len); | |||
#if (ERL_NIF_MAJOR_VERSION >= 2) && (ERL_NIF_MINOR_VERSION >= 12) | |||
nth = enif_hash(ERL_NIF_INTERNAL_HASH, argv[2], 0) % len; | |||
#else | |||
// Select the correct tracer for this process. | |||
// | |||
// The pid value is detailed in: | |||
// 5b6dd0e84cf0f1dc19ddd05f86cf04b2695d8a9e/erts/emulator/beam/erl_term.h#L498 | |||
// | |||
// As can be seen there, the first four bits of the pid value | |||
// are always the same. We therefore shift them out. | |||
ErlNifPid tracee; | |||
if (!enif_get_local_pid(env, argv[2], &tracee)) | |||
return atom_ok; | |||
nth = (tracee.pid >> 4) % len; | |||
#endif | |||
if (!enif_get_map_value(env, tracers, enif_make_int(env, nth), &head)) | |||
return atom_ok; | |||
if (!enif_get_local_pid(env, head, &tracer)) | |||
return atom_ok; | |||
// Everything good. Generate a timestamp to include in the message. | |||
ts = enif_make_int64(env, enif_monotonic_time(ERL_NIF_USEC)); | |||
// Build the message. There can be two different messages | |||
// depending on whether the extra option was set: | |||
// | |||
// - {Tag, Tracee, Ts, Term} | |||
// - {Tag, Tracee, Ts, Term, Extra} | |||
// | |||
// On top of that when match specs are enabled we may have | |||
// one additional term at the end of the tuple containing | |||
// the result of the match spec function. | |||
// | |||
// - {Tag, Tracee, Ts, Term, Result} | |||
// - {Tag, Tracee, Ts, Term, Extra, Result} | |||
has_extra = enif_get_map_value(env, argv[4], atom_extra, &extra); | |||
has_mspec = enif_get_map_value(env, argv[4], atom_match_spec_result, &mspec); | |||
if (has_extra && has_mspec) | |||
msg = enif_make_tuple6(env, argv[0], argv[2], ts, argv[3], extra, mspec); | |||
else if (has_extra) | |||
msg = enif_make_tuple5(env, argv[0], argv[2], ts, argv[3], extra); | |||
else if (has_mspec) | |||
msg = enif_make_tuple5(env, argv[0], argv[2], ts, argv[3], mspec); | |||
else | |||
msg = enif_make_tuple4(env, argv[0], argv[2], ts, argv[3]); | |||
// Send the message to the selected tracer. | |||
enif_send(env, &tracer, NULL, msg); | |||
return atom_ok; | |||
} | |||
static ErlNifFunc nif_funcs[] = { | |||
NIF_FUNCTIONS(NIF_FUNCTION_ARRAY) | |||
}; | |||
ERL_NIF_INIT(lg_tracer, nif_funcs, load, NULL, upgrade, unload) |
@ -0,0 +1,195 @@ | |||
// Copyright (c) 2014-2015, Loïc Hoguin <essen@ninenines.eu> | |||
// | |||
// Permission to use, copy, modify, and/or distribute this software for any | |||
// purpose with or without fee is hereby granted, provided that the above | |||
// copyright notice and this permission notice appear in all copies. | |||
// | |||
// THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES | |||
// WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF | |||
// MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR | |||
// ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES | |||
// WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN | |||
// ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF | |||
// OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE. | |||
#include "nif_helpers.h" | |||
#include <sys/queue.h> | |||
#include <stdarg.h> | |||
extern ERL_NIF_TERM atom_ok; | |||
extern ERL_NIF_TERM atom__nif_thread_ret_; | |||
typedef struct nif_thread_message { | |||
TAILQ_ENTRY(nif_thread_message) next_entry; | |||
ErlNifPid* from_pid; | |||
void* function; | |||
nif_thread_arg* args; | |||
} nif_thread_message; | |||
typedef TAILQ_HEAD(nif_thread_mailbox, nif_thread_message) nif_thread_mailbox; | |||
typedef struct { | |||
ErlNifTid tid; | |||
ErlNifMutex* lock; | |||
ErlNifCond* cond; | |||
nif_thread_mailbox* mailbox; | |||
} nif_thread_state; | |||
// Message. | |||
static nif_thread_message* nif_thread_message_alloc(void* f, nif_thread_arg* args, ErlNifPid* pid) | |||
{ | |||
nif_thread_message* msg = (nif_thread_message*)enif_alloc(sizeof(nif_thread_message)); | |||
msg->from_pid = pid; | |||
msg->function = f; | |||
msg->args = args; | |||
return msg; | |||
} | |||
static void nif_thread_message_free(nif_thread_message* msg) | |||
{ | |||
enif_free(msg->from_pid); | |||
enif_free(msg->args); | |||
enif_free(msg); | |||
} | |||
// Calls and casts. | |||
static ERL_NIF_TERM nif_thread_send(nif_thread_state* st, nif_thread_message* msg) | |||
{ | |||
enif_mutex_lock(st->lock); | |||
TAILQ_INSERT_TAIL(st->mailbox, msg, next_entry); | |||
enif_cond_signal(st->cond); | |||
enif_mutex_unlock(st->lock); | |||
return atom_ok; | |||
} | |||
ERL_NIF_TERM nif_thread_cast(ErlNifEnv* env, void (*f)(nif_thread_arg*), int a, ...) | |||
{ | |||
va_list ap; | |||
int i; | |||
nif_thread_arg* args = (nif_thread_arg*)enif_alloc(a * sizeof(nif_thread_arg)); | |||
va_start(ap, a); | |||
for (i = 0; i < a; i++) | |||
args[i] = va_arg(ap, void*); | |||
va_end(ap); | |||
nif_thread_message* msg = nif_thread_message_alloc(f, args, NULL); | |||
return nif_thread_send((nif_thread_state*)enif_priv_data(env), msg); | |||
} | |||
ERL_NIF_TERM nif_thread_call(ErlNifEnv* env, ERL_NIF_TERM (*f)(ErlNifEnv*, nif_thread_arg*), int a, ...) | |||
{ | |||
va_list ap; | |||
int i; | |||
nif_thread_arg* args = (nif_thread_arg*)enif_alloc(a * sizeof(nif_thread_arg)); | |||
va_start(ap, a); | |||
for (i = 0; i < a; i++) | |||
args[i] = va_arg(ap, void*); | |||
va_end(ap); | |||
ErlNifPid* pid = (ErlNifPid*)enif_alloc(sizeof(ErlNifPid)); | |||
nif_thread_message* msg = nif_thread_message_alloc((void*)f, args, enif_self(env, pid)); | |||
return nif_thread_send((nif_thread_state*)enif_priv_data(env), msg); | |||
} | |||
// Main thread loop. | |||
static int nif_thread_receive(nif_thread_state* st, nif_thread_message** msg) | |||
{ | |||
enif_mutex_lock(st->lock); | |||
while (TAILQ_EMPTY(st->mailbox)) | |||
enif_cond_wait(st->cond, st->lock); | |||
*msg = TAILQ_FIRST(st->mailbox); | |||
TAILQ_REMOVE(st->mailbox, TAILQ_FIRST(st->mailbox), next_entry); | |||
enif_mutex_unlock(st->lock); | |||
if ((*msg)->function == NULL) | |||
return 0; | |||
return 1; | |||
} | |||
static void nif_thread_handle(ErlNifEnv* env, nif_thread_state* st, nif_thread_message* msg) | |||
{ | |||
if (msg->from_pid == NULL) { | |||
void (*cast)(nif_thread_arg*) = msg->function; | |||
cast(msg->args); | |||
} else { | |||
ERL_NIF_TERM (*call)(ErlNifEnv*, nif_thread_arg*) = msg->function; | |||
ERL_NIF_TERM ret = call(env, msg->args); | |||
enif_send(NULL, msg->from_pid, env, | |||
enif_make_tuple2(env, atom__nif_thread_ret_, ret)); | |||
enif_clear_env(env); | |||
} | |||
nif_thread_message_free(msg); | |||
} | |||
static void* nif_main_thread(void* obj) | |||
{ | |||
ErlNifEnv* env = enif_alloc_env(); | |||
nif_thread_state* st = (nif_thread_state*)obj; | |||
nif_thread_message* msg; | |||
while (nif_thread_receive(st, &msg)) | |||
nif_thread_handle(env, st, msg); | |||
enif_free_env(env); | |||
return NULL; | |||
} | |||
// Main thread creation/destruction. | |||
void* nif_create_main_thread(char* name) | |||
{ | |||
nif_thread_state* st = (nif_thread_state*)enif_alloc(sizeof(nif_thread_state)); | |||
st->lock = enif_mutex_create("nif_thread_mailbox_lock"); | |||
st->cond = enif_cond_create("nif_thread_mailbox_cond"); | |||
st->mailbox = (nif_thread_mailbox*)enif_alloc(sizeof(nif_thread_mailbox)); | |||
TAILQ_INIT(st->mailbox); | |||
#if defined(__APPLE__) && defined(__MACH__) | |||
// On OSX we identify ourselves as the main thread to ensure that | |||
// we are compatible with libraries that require it. For example | |||
// this is necessary with SDL2 in order to receive input events. | |||
erl_drv_steal_main_thread(name, &(st->tid), nif_main_thread, st, NULL); | |||
#else | |||
enif_thread_create(name, &(st->tid), nif_main_thread, st, NULL); | |||
#endif | |||
return (void*)st; | |||
} | |||
void nif_destroy_main_thread(void* void_st) | |||
{ | |||
nif_thread_state* st = (nif_thread_state*)void_st; | |||
nif_thread_message* msg = nif_thread_message_alloc(NULL, NULL, NULL); | |||
nif_thread_send(st, msg); | |||
enif_thread_join(st->tid, NULL); | |||
enif_cond_destroy(st->cond); | |||
enif_mutex_destroy(st->lock); | |||
enif_free(st->mailbox); | |||
enif_free(st); | |||
} |
@ -0,0 +1,139 @@ | |||
// Copyright (c) 2014-2015, Loïc Hoguin <essen@ninenines.eu> | |||
// | |||
// Permission to use, copy, modify, and/or distribute this software for any | |||
// purpose with or without fee is hereby granted, provided that the above | |||
// copyright notice and this permission notice appear in all copies. | |||
// | |||
// THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES | |||
// WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF | |||
// MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR | |||
// ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES | |||
// WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN | |||
// ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF | |||
// OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE. | |||
#ifndef __NIF_HELPERS_H__ | |||
#define __NIF_HELPERS_H__ | |||
#include "erl_nif.h" | |||
#define TO_STRING(i) #i | |||
// Atoms. | |||
#define MAX_ATOM_LENGTH 255 | |||
#define NIF_ATOM_DECL(a) ERL_NIF_TERM atom_ ## a; | |||
#define NIF_ATOM_H_DECL(a) extern ERL_NIF_TERM atom_ ## a; | |||
#define NIF_ATOM_INIT(a) atom_ ## a = enif_make_atom(env, #a); | |||
// Functions. | |||
#ifndef NIF_FUNCTION_NAME | |||
#define NIF_FUNCTION_NAME(n) n | |||
#endif | |||
#define NIF_FUNCTION(f) \ | |||
ERL_NIF_TERM NIF_FUNCTION_NAME(f)(ErlNifEnv* env, int argc, const ERL_NIF_TERM argv[]) | |||
#define NIF_FUNCTION_ARRAY(f, a) {#f, a, NIF_FUNCTION_NAME(f)}, | |||
#define NIF_FUNCTION_H_DECL(f, a) \ | |||
ERL_NIF_TERM NIF_FUNCTION_NAME(f)(ErlNifEnv*, int, const ERL_NIF_TERM []); | |||
#define BADARG_IF(cond) if (cond) return enif_make_badarg(env) | |||
// Resources. | |||
#ifndef NIF_RES_TYPE | |||
#define NIF_RES_TYPE(t) t | |||
#endif | |||
#define NIF_RES_DECL(r) ErlNifResourceType* res_ ## r = NULL; | |||
#define NIF_RES_H_DECL(r) \ | |||
extern ErlNifResourceType* res_ ## r; \ | |||
void dtor_ ## r(ErlNifEnv*, void*); \ | |||
typedef struct { \ | |||
NIF_RES_TYPE(r)* v; \ | |||
void* dep; \ | |||
} obj_ ## r; | |||
#define NIF_RES_INIT(r) \ | |||
res_ ## r = enif_open_resource_type(env, NULL, TO_STRING(NIF_RES_TYPE(r)), dtor_ ## r, ERL_NIF_RT_CREATE, NULL); \ | |||
if (!res_ ## r) return -1; | |||
#define NIF_RES_GET(r, obj) (((obj_ ## r*)obj)->v) | |||
#define NIF_RES_DEP(r, obj) (((obj_ ## r*)obj)->dep) | |||
#define NIF_RES_TO_TERM(r, val, term) NIF_RES_TO_TERM_WITH_DEP(r, val, term, NULL) | |||
#define NIF_RES_TO_TERM_WITH_DEP(r, val, term, dep_res) { \ | |||
obj_ ## r* res = enif_alloc_resource(res_ ## r, sizeof(obj_ ## r)); \ | |||
res->v = val; \ | |||
res->dep = dep_res; \ | |||
term = enif_make_resource(env, res); \ | |||
enif_release_resource(res); \ | |||
} | |||
// Function generators. | |||
#define NIF_ATOM_TO_FLAG(a, f) if (enif_is_identical(atom_ ## a, head)) *flags |= f; else | |||
#define NIF_LIST_TO_FLAGS_FUNCTION(f, type, flags_list) \ | |||
int f(ErlNifEnv* env, ERL_NIF_TERM list, type* flags) \ | |||
{ \ | |||
ERL_NIF_TERM head; \ | |||
\ | |||
if (!enif_is_list(env, list)) \ | |||
return 0; \ | |||
\ | |||
while (enif_get_list_cell(env, list, &head, &list)) { \ | |||
flags_list(NIF_ATOM_TO_FLAG) /* else */ return 0; \ | |||
} \ | |||
\ | |||
return 1; \ | |||
} | |||
#define NIF_FLAG_CONS_LIST(a, f) if (flags & f) list = enif_make_list_cell(env, atom_ ## a, list); | |||
#define NIF_FLAGS_TO_LIST_FUNCTION(f, type, flags_list) \ | |||
ERL_NIF_TERM f(ErlNifEnv* env, type flags) \ | |||
{ \ | |||
ERL_NIF_TERM list = enif_make_list(env, 0); \ | |||
flags_list(NIF_FLAG_CONS_LIST); \ | |||
return list; \ | |||
} | |||
#define NIF_ATOM_TO_ENUM(a, e) if (enif_is_identical(atom_ ## a, atom)) { *val = e; return 1; } | |||
#define NIF_ATOM_TO_ENUM_FUNCTION(f, type, enum_list) \ | |||
int f(ErlNifEnv* env, ERL_NIF_TERM atom, type* val) \ | |||
{ \ | |||
enum_list(NIF_ATOM_TO_ENUM) \ | |||
\ | |||
return 0; \ | |||
} | |||
#define NIF_ATOM_TO_ENUM_FUNCTION_DECL(f, type) int f(ErlNifEnv*, ERL_NIF_TERM, type*); | |||
#define NIF_ENUM_TO_ATOM(a, e) if (id == e) return atom_ ## a; | |||
#define NIF_ENUM_TO_ATOM_FUNCTION(f, type, enum_list) \ | |||
ERL_NIF_TERM f(type id) \ | |||
{ \ | |||
enum_list(NIF_ENUM_TO_ATOM) \ | |||
return atom_undefined; \ | |||
} | |||
#define NIF_ENUM_TO_ATOM_FUNCTION_DECL(f, type) ERL_NIF_TERM f(type); | |||
// Threaded NIFs. | |||
typedef void* nif_thread_arg; | |||
#ifdef __cplusplus | |||
extern "C" { | |||
#endif | |||
void* nif_create_main_thread(char*); | |||
void nif_destroy_main_thread(void*); | |||
ERL_NIF_TERM nif_thread_cast(ErlNifEnv*, void (*f)(nif_thread_arg*), int a, ...); | |||
ERL_NIF_TERM nif_thread_call(ErlNifEnv*, ERL_NIF_TERM (*f)(ErlNifEnv*, nif_thread_arg*), int a, ...); | |||
#ifdef __cplusplus | |||
} | |||
#endif | |||
#define NIF_CAST_HANDLER(f) static void f(nif_thread_arg* args) | |||
#define NIF_CALL_HANDLER(f) static ERL_NIF_TERM f(ErlNifEnv* env, nif_thread_arg* args) | |||
#endif |
@ -0,0 +1,7 @@ | |||
{erl_opts, [debug_info]}. | |||
{deps, []}. | |||
{shell, [ | |||
% {config, "config/sys.config"}, | |||
{apps, [eTpf]} | |||
]}. |
@ -0,0 +1,11 @@ | |||
= Looking Glass User Guide | |||
include::introduction.asciidoc[Introduction] | |||
include::tracing.asciidoc[Tracing] | |||
include::callgrind.asciidoc[Callgrind profiling] | |||
include::flame.asciidoc[Flame graph profiling] | |||
include::messages.asciidoc[Messages profiling] |
@ -0,0 +1,176 @@ | |||
[[callgrind]] | |||
== Callgrind profiling | |||
Looking Glass' primary purpose is the profiling of | |||
Erlang applications. This is done by first tracing | |||
events to a file or socket and then processing it | |||
to extract useful output. | |||
Profiling tools generally have a few different types | |||
of output. This chapter is about callgrind output, | |||
which can be read using the `qcachegrind`/`kcachegrind` | |||
tool. | |||
=== Quick start | |||
Assuming you generated trace files using the profile | |||
mode and the running flag, as detailed in the | |||
xref:tracing_running[Tracing chapter], you can | |||
generate callgrind.out files using the following | |||
command: | |||
[source,erlang] | |||
---- | |||
1> lg_callgrind:profile_many("traces.lz4.*", "callgrind.out", | |||
#{running => true}). | |||
---- | |||
This will create a callgrind.out file for all trace files | |||
you generated. For example if you had 'traces.lz4.1' and | |||
'traces.lz4.2', you should now also have 'callgrind.out.1' | |||
and 'callgrind.out.2'. | |||
You can now open these two files in the cachegrind tool, | |||
either from the user interface or from the command line: | |||
[source,bash] | |||
---- | |||
$ qcachegrind callgrind.out | |||
---- | |||
It will automatically detect and open all files matching | |||
the `callgrind.out.*` pattern. | |||
=== Profiling one file | |||
You can profile one file by calling the function | |||
`lg_callgrind:profile/2,3`. It takes the trace file name, | |||
the output file name and an optional map of options: | |||
[source,erlang] | |||
---- | |||
1> lg_callgrind:profile("traces.lz4.1", "callgrind.out.1"). | |||
---- | |||
It also accepts options: | |||
[source,erlang] | |||
---- | |||
1> lg_callgrind:profile("traces.lz4.1", "callgrind.out.1", | |||
#{running => true}). | |||
---- | |||
=== Profiling many files | |||
A convenience function is available for profiling many | |||
files at once: `lg_callgrind:profile_many/2,3`. It takes | |||
a wildcard pattern as first argument and a file name | |||
prefix as second argument: | |||
[source,erlang] | |||
---- | |||
1> lg_callgrind:profile_many("traces.lz4.*", "callgrind.out"). | |||
---- | |||
If there were two trace files, this will result in two | |||
'callgrind.out' files: 'callgrind.out.1' and 'callgrind.out.2'. | |||
It also accepts options: | |||
[source,erlang] | |||
---- | |||
1> lg_callgrind:profile_many("traces.lz4.*", "callgrind.out", | |||
#{running => true}). | |||
---- | |||
=== Running information | |||
When the trace files contain running information, meaning | |||
they were created with the `running` flag enabled, you | |||
need to also pass the `running` flag to the profiler in | |||
order to have that information available in 'callgrind.out' | |||
files: | |||
[source,erlang] | |||
---- | |||
1> lg_callgrind:profile_many("traces.lz4.*", "callgrind.out", | |||
#{running => true}). | |||
---- | |||
=== Scope | |||
By default the scope of the trace events is global. This | |||
means that the cachegrind tool will group all events | |||
together regardless of where they happened. This is | |||
useful to see which functions take the most resources | |||
overall. | |||
Other times you may want to see which *processes* take | |||
the most resources. To do this you need to instruct | |||
Looking Glass to keep the process information when | |||
generating the 'callgrind.out' files. This is done | |||
using the `scope` option: | |||
[source,erlang] | |||
---- | |||
1> lg_callgrind:profile_many("traces.lz4.*", "callgrind.out", | |||
#{scope => per_process}). | |||
---- | |||
=== Using the cachegrind tool | |||
There are a few gotchas to be aware of when using the | |||
cachegrind tool with the output generated by Looking Glass. | |||
The cachegrind tool was built with imperative code in mind. | |||
It does not deal too well with recursion. This means that | |||
the number of times functions are called might not always | |||
be correct, especially for functions that call themselves. | |||
You can see an example of this issue when looking at the | |||
call graph, for example. | |||
Looking Glass uses ELF Object field for storing the pid of | |||
the process when the `scope => per_process` option is used. | |||
This allows you to investigate processes individually by | |||
using the 'grouping' feature and selecting 'ELF Object'. | |||
You can then see which processes take the most resources | |||
and look at the function calls within those processes. | |||
When the running flag is used, the following event types | |||
are generated: | |||
* Total time in microseconds | |||
* Active time in microseconds | |||
* Wait time in microseconds (scheduled out) | |||
* Number of times the process was scheduled out | |||
The following formula is true: `Total = Active + Wait`. | |||
The wait time is the time spent when the process was | |||
scheduled out, in other words it was not running. This | |||
happens in a number of different places, like receive | |||
clauses or when the reduction count reached zero. | |||
The number of times the process was scheduled out may | |||
or may not be accurate at this time. Another part that | |||
may not be accurate is the time spent doing port | |||
operations which may appear as active time when the | |||
process is mostly waiting. Both will be improved | |||
in the future. | |||
While Looking Glass provides line number information | |||
about the various calls, it is not able to identify | |||
which function clause was involved during this call. | |||
This means that the call information for functions | |||
with a lot of clauses will get aggregated at the same | |||
line number when looking at the source code in the | |||
cachegrind tool. This has an important impact on | |||
most standard behaviors, including `handle_event` | |||
from `gen_statem`. You can however structure your | |||
code so that clause-heavy functions only dispatch | |||
to other functions, in turn getting a better view | |||
in the cachegrind tool. | |||
Looking Glass is not able to find the line number | |||
of list comprehensions and funs at this time. They | |||
will always point to line number 1. |
@ -0,0 +1,82 @@ | |||
[[flame]] | |||
== Flame graph profiling | |||
As an alternative to xref:callgrind[Callgrind output], | |||
Looking Glass provides flame graphs. Flame graphs are | |||
a graphical view of stack traces that make it obvious | |||
where the most time is spent. It complements the other | |||
graphical views provided by `qcachegrind`. | |||
Looking Glass only takes care of providing an output | |||
that can then be converted into a flame graph using | |||
the usual tool (not included). This chapter will | |||
explain both operations. | |||
=== Required trace options | |||
In order to generate a flame graph we currently need to | |||
use one additional option when tracing. This option will | |||
result in adding stack trace information to call events. | |||
The option is `process_dump` and it must be set to `true`. | |||
To give an example, instead of this: | |||
[source,erlang] | |||
---- | |||
1> lg:trace('_', lg_file_tracer, "traces.lz4"). | |||
---- | |||
Do this: | |||
[source,erlang] | |||
---- | |||
1> lg:trace('_', lg_file_tracer, "traces.lz4", | |||
#{process_dump => true}). | |||
---- | |||
=== Profiling one file | |||
The `lg_flame` module provides a similar interface as other | |||
Looking Glass profilers. You can produce an intermediate | |||
output based on one or many files. | |||
To profile one file: | |||
[source,erlang] | |||
---- | |||
1> lg_flame:profile("traces.lz4.1", "output"). | |||
---- | |||
This will create an intermediate file named 'output'. | |||
=== Profiling many files | |||
To profile many files: | |||
[source,erlang] | |||
---- | |||
1> lg_flame:profile_many("traces.lz4.*", "output"). | |||
---- | |||
Note that the output is always a single file as the | |||
results are merged together. | |||
=== Building the flame graph | |||
https://github.com/brendangregg/FlameGraph[flamegraph.pl] | |||
can be used to produce actual SVG flame graphs. | |||
First we need to clone it. Anywhere will do: | |||
[source,bash] | |||
$ git clone https://github.com/brendangregg/FlameGraph | |||
Then we can use it on our output file to create an SVG: | |||
[source,bash] | |||
$ ./FlameGraph/flamegraph.pl output > output.svg | |||
You can then open the output SVG in your Web browser | |||
of choice. The produced SVG is interactive, you can | |||
click on the different functions to zoom in, and you | |||
can also search for a specific function call. |
@ -0,0 +1,41 @@ | |||
[[introduction]] | |||
== Introduction | |||
Looking Glass is a tracer and profiler for Erlang/OTP. | |||
Looking Glass is the next generation profiling tool. It | |||
is implemented as an `erl_tracer` NIF and thus requires | |||
Erlang/OTP 19.0 or above. | |||
Looking Glass aims to provide a very efficient tool | |||
usable both in development and production settings, | |||
and capable of running for a very long amount of time | |||
even on busy systems. | |||
=== Supported platforms | |||
Looking Glass is currently developed on Linux but should | |||
also work on OSX and Windows. | |||
Looking Glass requires Erlang/OTP 19.0 or above. | |||
A cachegrind tool is required for reading the output | |||
from `lg_callgrind`. The `qcachegrind` tool (also | |||
known as `kcachegrind`) is recommended. Note that | |||
it is a good idea to also install `graphviz` to | |||
have the quite informative call graphs. | |||
=== Requirements | |||
Looking Glass requires a C compiler toolchain and an `lz4` library to be installed. | |||
=== License | |||
Looking Glass is double-licensed under the Mozilla | |||
Public License 1.1 and the Apache License version 2. | |||
See the LICENSE file for more information. | |||
=== Versioning | |||
Looking Glass uses https://semver.org/[Semantic Versioning 2.0.0]. |
@ -0,0 +1,254 @@ | |||
[[messages]] | |||
== Messages profiling | |||
Looking Glass can also be used to profile Erlang processes | |||
based on the messages they send. It can help you detect | |||
which processes are the most busy and is able to generate | |||
graphs and sequence diagrams to help you debug complex | |||
issues. | |||
=== Enabling the tracing of messages | |||
By default Looking Glass will not include the messages | |||
in the trace files. It needs to be enabled through the | |||
xref:tracing_send[send option]. | |||
The output from one tracing session can then be used | |||
for both callgrind and message profiling. | |||
=== Profiling one file | |||
You can profile one file by calling the function | |||
`lg_messages:profile/1`. It takes the trace file name | |||
and prints out the result of the profiling. | |||
[source,erlang] | |||
---- | |||
1> lg_messages:profile("traces.lz4.1"). | |||
---- | |||
It will also create a GraphViz file currently hardcoded as | |||
'digraph.gv' and print further instructions to use it. | |||
=== Profiling many files | |||
A convenience function is available for profiling many | |||
files at once: `lg_callgrind:profile_many/2,3`. It takes | |||
a wildcard pattern as first argument and a file name | |||
prefix as second argument: | |||
You can profile many files by calling the function | |||
`lg_messages:profile_many/1`. It takes a wildcard pattern | |||
and prints out the result of the profiling. The result | |||
is a merge of the events in the different trace files. | |||
[source,erlang] | |||
---- | |||
1> lg_messages:profile_many("traces.lz4.*"). | |||
---- | |||
=== Profile output | |||
The profile step will result in four tables being printed. | |||
* The first table shows the processes that sent the most messages. | |||
* The second table shows the processes that sent the most messages | |||
to processes that are either dead or never existed in the first place. | |||
* The third table shows the processes that were most frequently sending | |||
messages to one specific other process (from Alice to Bob). | |||
* The last table shows the processes that were exchanging the most | |||
messages (from Alice to Bob, and from Bob to Alice). | |||
.Example output | |||
---- | |||
1> lg_messages:profile_many("traces.lz4.*"). | |||
They sent the most messages | |||
=========================== | |||
Process ID Count Most recent message | |||
---------- ----- ------------------- | |||
<7782.367.0> 147327 {notify,{event,channel_closed,...}} | |||
<7782.356.0> 73035 {notify,{event,connection_closed,...}} | |||
<7782.382.0> 30514 pause | |||
<7782.391.0> 30052 {'$gen_cast',{deliver,{...},...}} | |||
<7782.365.0> 1486 {channel_exit,1,{writer,...}} | |||
[...] | |||
They sent the most messages to dead processes | |||
============================================= | |||
Process ID Count Most recent message | |||
---------- ----- ------------------- | |||
<7782.367.0> 29 {notify,{event,channel_closed,...}} | |||
They sent the most messages to one other process | |||
================================================ | |||
From pid To pid Count Most recent message | |||
-------- ------ ----- ------------------- | |||
<7782.367.0> <7782.365.0> 74318 {notify,{event,channel_closed,...}} | |||
<7782.356.0> <7782.367.0> 73001 {notify,{event,connection_closed,...}} | |||
<7782.367.0> <7782.375.0> 73000 {notify,{event,channel_closed,...}} | |||
<7782.382.0> <7782.391.0> 30202 pause | |||
<7782.391.0> <7782.375.0> 29894 {'$gen_cast',{deliver,{...},...}} | |||
<7782.365.0> <7782.375.0> 1485 {channel_exit,1,{writer,...}} | |||
[...] | |||
They sent the most messages to each other | |||
========================================= | |||
Count Pid 1 Most recent message | |||
Pid 2 from the corresponding process | |||
----- ----- ------------------------------ | |||
74318 <7782.365.0> {channel_exit,1,{writer,...}} | |||
<7782.367.0> {notify,{event,channel_closed,...}} | |||
73001 <7782.356.0> {notify,{event,connection_closed,...}} | |||
<7782.367.0> {notify,{event,channel_closed,...}} | |||
73000 <7782.367.0> {notify,{event,channel_closed,...}} | |||
<7782.375.0> '<none>' | |||
30351 <7782.382.0> pause | |||
<7782.391.0> {'$gen_cast',{deliver,{...},...}} | |||
29894 <7782.375.0> '<none>' | |||
<7782.391.0> {'$gen_cast',{deliver,{...},...}} | |||
[...] | |||
The file digraph.gv was created. Use GraphViz to make a PNG. | |||
$ dot -Tpng -O digraph.gv | |||
You can also edit the file to remove uninteresting processes. | |||
One line in the file is equal to a connection between two processes. | |||
---- | |||
At the end of the output, instructions are given to generate an | |||
image from a GraphViz file. This image shows the relationships | |||
between the processes and indicates how many messages they send | |||
to each other. | |||
The file generated by Looking Glass is a text file that can be | |||
further edited as necessary. It looks like this: | |||
---- | |||
digraph { | |||
concentrate=true; | |||
splines=ortho; | |||
edge [arrowhead=none, labelfontsize=12.0, minlen=3]; | |||
"error_logger" -> "<7782.354.0>" [taillabel=0, headlabel=2]; | |||
"<7782.32.0>" -> "<7782.380.0>" [taillabel=0, headlabel=1]; | |||
"<7782.388.0>" -> "<7782.391.0>" [taillabel=0, headlabel=1]; | |||
"error_logger" -> "<7782.355.0>" [taillabel=0, headlabel=4]; | |||
[...] | |||
} | |||
---- | |||
It is of course possible to edit this file. You may want to | |||
modify the style attributes, or even remove processes from | |||
the output entirely. | |||
=== Generating sequence diagrams | |||
Looking Glass can also be used to extract the sequence of messages | |||
exchanged between two or more processes. This is done using the | |||
`lg_messages_seqdiag` module, which works just like `lg_messages` | |||
ecept the functions take a second argument containing the list of | |||
pids you wish to investigate. | |||
To look at one file: | |||
[source,erlang] | |||
---- | |||
1> lg_messages_seqdiag:profile("traces.lz4.1", | |||
["<7788.381.0>", "<7788.382.0>", "<7774.383.0>", | |||
"<7774.384.0>", "<7774.386.0>"]). | |||
---- | |||
And many files: | |||
[source,erlang] | |||
---- | |||
1> lg_messages_seqdiag:profile_many("traces.lz4.*", | |||
["<7788.381.0>", "<7788.382.0>", "<7774.383.0>", | |||
"<7774.384.0>", "<7774.386.0>"]). | |||
---- | |||
The list of pids must be given as a list of strings. This is | |||
because the processes represented do not exist on the running | |||
system. Looking Glass will ignore the node information from the | |||
pid too, so you do not need to worry about it. This explains why | |||
the pids requested in the previous two snippets look as if they | |||
come from different nodes. The pids `"<7888.381.0>"` and | |||
`"<7774.381.0>"` are therefore equivalent. | |||
After running one of these commands, you will end up with a | |||
file 'seq.diag' that can then be used to create an image. This | |||
file can also be edited later on if necessary. It looks like this: | |||
---- | |||
seqdiag { | |||
edge_length = 300; | |||
activation = none; | |||
"<7774.382.0>" -> "<7774.381.0>" [label="gen:call #1 {start_child,{collector,{rabbit_queue_collector,start_link,[...]},intrinsic,30000,worker,...}}"]; | |||
"<7774.383.0>" -> "<7774.381.0>" [label="{ack,<7774.383.0>,{ok,<7774.383.0>}}"]; | |||
"<7774.381.0>" -> "<7774.382.0>" [label="#1 {ok,<7774.383.0>}"]; | |||
[...] | |||
} | |||
---- | |||
Before you can create an image from it, you will need to install | |||
`seqdiag`. Installation instructions will depend on your system. | |||
The project page is at http://blockdiag.com/en/seqdiag/ | |||
.Example output | |||
image::seq.png[] | |||
=== Identifying processes | |||
While Looking Glass will display the pid and one sample message | |||
from each process, it's not always ideal to identify which process | |||
is which. | |||
To allievate that, Looking Glass offers a simple solution: | |||
sending a message to the named process `lg` while a tracer is | |||
running. Looking Glass will inevitably log this message in the | |||
trace file, recognize that the target is `lg` and use the | |||
message as metadata. This metadata is then available to any | |||
module reading from the trace file. | |||
The process is only available when Looking Glass is running, | |||
of course, which means we can't just send a message directly. | |||
The following works: | |||
[source,erlang] | |||
---- | |||
is_pid(whereis(lg)) andalso (lg ! Info). | |||
---- | |||
This can be made into a macro, of course: | |||
[source,erlang] | |||
---- | |||
%% Store metadata in the trace files when message tracing is enabled. | |||
-define(LG_INFO(Info), is_pid(whereis(lg)) andalso (lg ! Info)). | |||
---- | |||
And can then be used like this: | |||
[source,erlang] | |||
---- | |||
?LG_INFO(#{process_type => reader}). | |||
---- | |||
The message must always be a map. Reading the trace file | |||
will otherwise fail. Looking Glass only recognizes the | |||
`process_type` field, and uses it as a label to identify | |||
processes when profiling exchanges of messages. You are | |||
free to define any other value you need in the map. | |||
The metadata can also be updated by sending another message | |||
or by calling the macro a second time. The operation done | |||
on the map will be a merge by default. |
@ -0,0 +1,367 @@ | |||
[[tracing]] | |||
== Tracing | |||
Looking Glass is both a tracing and a profiling tool. | |||
In this chapter we will take a look at the tracing | |||
capabilities of the tool, and also learn how to create | |||
trace files which are necessary for profiling. | |||
=== First steps | |||
Let's start by tracing everything. | |||
Open an Erlang shell and run the following command: | |||
[source,erlang] | |||
---- | |||
1> lg:trace('_'). | |||
{link,<0.4.0>,1488297881224444,#Port<0.692>} | |||
{getting_unlinked,<0.4.0>,1488297881224533,#Port<0.692>} | |||
{link,<0.4.0>,1488297881224640,#Port<0.693>} | |||
{getting_unlinked,<0.4.0>,1488297881224720,#Port<0.693>} | |||
{link,<0.4.0>,1488297881224817,#Port<0.694>} | |||
{getting_unlinked,<0.4.0>,1488297881224881,#Port<0.694>} | |||
{link,<0.4.0>,1488297881224979,#Port<0.695>} | |||
{getting_unlinked,<0.4.0>,1488297881225060,#Port<0.695>} | |||
... | |||
---- | |||
As you can see we get a lot of output. That's because | |||
the `lg:trace/1` function will by default output the | |||
raw trace events to the console. We also used the atom | |||
`'_'` to tell Looking Glass to trace all modules, and | |||
didn't restrict which process should be traced. | |||
Needless to say, do not do this in production. | |||
The trace events always come with an event name, the pid | |||
of the process where the event happened, a timestamp in | |||
microseconds and one or two extra elements providing | |||
extra context about the event. | |||
For example the following event is a function call occuring | |||
in the process `<0.64.0>` at timestamp `1488297891226328` | |||
to `supervisor:handle_info/2`. | |||
[source,erlang] | |||
---- | |||
{call,<0.64.0>,1488297891226328,{supervisor,handle_info,2}} | |||
---- | |||
=== Stop tracing | |||
To stop tracing, simply call: | |||
[source,erlang] | |||
---- | |||
2> lg:stop(). | |||
---- | |||
=== Tracing specific modules | |||
In order to get a more interesting output we need to filter | |||
what will be traced. We may for example only want the events | |||
from the module `shell`: | |||
[source,erlang] | |||
---- | |||
1> lg:trace(shell). | |||
... | |||
{call,<0.58.0>,1488298545020494,{shell,result_will_be_saved,0}} | |||
{call,<0.58.0>,1488298545020497,{shell,get_history_and_results,0}} | |||
{call,<0.58.0>,1488298545020498,{shell,get_env,2}} | |||
{return_to,<0.58.0>,1488298545020501,{shell,get_history_and_results,0}} | |||
{call,<0.58.0>,1488298545020502,{shell,get_env,2}} | |||
{return_to,<0.58.0>,1488298545020503,{shell,get_history_and_results,0}} | |||
{return_to,<0.58.0>,1488298545020504,{shell,result_will_be_saved,0}} | |||
... | |||
---- | |||
We can also request to trace a list of modules: | |||
[source,erlang] | |||
---- | |||
1> lg:trace([shell, user_drv]). | |||
... | |||
{call,<0.58.0>,1488299067458321,{shell,record_print_fun,1}} | |||
{return_to,<0.58.0>,1488299067458322,{shell,pp,4}} | |||
{call,<0.58.0>,1488299067458323,{shell,enc,0}} | |||
{call,<0.49.0>,1488299067459603,{user_drv,handle_req,4}} | |||
{call,<0.49.0>,1488299067459605,{user_drv,get_unicode_state,1}} | |||
... | |||
---- | |||
=== Tracing applications | |||
In addition to providing modules, you can provide OTP applications. | |||
When you do so all the modules belonging to the application will | |||
be traced. We can of course trace Looking Glass itself: | |||
[source,erlang] | |||
---- | |||
1> lg:trace({app, looking_glass}). | |||
{link,<0.4.0>,1488299179652509,#Port<0.688>} | |||
{getting_unlinked,<0.4.0>,1488299179652621,#Port<0.688>} | |||
{call,<0.58.0>,1488299179653161,{lg,'-trace_patterns/1-fun-0-',1}} | |||
{call,<0.58.0>,1488299179653164,{lg,trace_pattern,1}} | |||
... | |||
---- | |||
Note that Looking Glass will disable tracing on the tracer processes | |||
themselves (to avoid an infinite recursion). More on that later. | |||
You can trace any combination of modules and applications: | |||
[source,erlang] | |||
---- | |||
1> lg:trace([shell, {app, looking_glass}]). | |||
... | |||
---- | |||
=== Tracing specific processes | |||
Looking Glass traces all processes by default. | |||
Large systems tend to have many processes and this can generate | |||
a lot of noise, especially if you are trying to optimize a | |||
specific component. | |||
You can specify which processes should be traced using the | |||
input option `scope`: | |||
[source,erlang] | |||
---- | |||
1> lg:trace([{scope, [self()]}, io]). | |||
{call,<0.58.0>,1489494935163831,{io,columns,0}} | |||
{call,<0.58.0>,1489494935163841,{io,default_output,0}} | |||
{return_to,<0.58.0>,1489494935163844,{io,columns,0}} | |||
{call,<0.58.0>,1489494935163846,{io,columns,1}} | |||
... | |||
---- | |||
The list found in the `scope` tuple can take the same values | |||
as the first argument to `erlang:trace/3`. When the tuple is | |||
missing the default will be `processes`. | |||
The scope tuple can be found multiple time in the input. | |||
This is particularly useful when combining trace definition | |||
callbacks. | |||
Looking Glass will trace all the processes specified but | |||
also the processes that they create. This means that when | |||
you provide a supervisor pid, all its children will also | |||
be traced, as long as they were started after the start | |||
of the trace session. | |||
=== Trace definition callbacks | |||
For ease of use, Looking Glass allows you to define functions in | |||
your code that return interesting patterns. This allows you to | |||
define areas of your code that you profile often, or to dynamically | |||
generate the list if necessary. | |||
To use callbacks, simply provide a callback tuple: | |||
[source,erlang] | |||
---- | |||
1> lg:trace({callback, lg_callgrind, patterns}). | |||
---- | |||
You can of course use it in combination with other inputs: | |||
[source,erlang] | |||
---- | |||
1> lg:trace([shell, {callback, lg_callgrind, patterns}]). | |||
---- | |||
You can also combine as many callbacks as you wish. | |||
The callback takes the following form: | |||
[source,erlang] | |||
---- | |||
patterns() -> lg:input(). | |||
---- | |||
The function name can be anything. A module may have more than one | |||
Looking Glass callback. | |||
The return value is a list of patterns and scopes that will | |||
be traced. It can therefore contain modules, applications | |||
or other callbacks. | |||
An example callback could be: | |||
[source,erlang] | |||
---- | |||
-module(ranch_lg). | |||
-export([connections/0]). | |||
%% Trace all events but only from the TCP connection processes. | |||
connections() -> | |||
ConnsPid = ranch_server:get_connections_sup(tcp_echo), | |||
['_', {scope, [ConnsPid]}]. | |||
---- | |||
=== Tracers | |||
Looking Glass comes with a number of tracers. The default is called | |||
`lg_raw_console_tracer` and simply outputs the events to the console, | |||
without any formatting applied. | |||
The default `lg:trace/1` call is equivalent to the following: | |||
[source,erlang] | |||
---- | |||
1> lg:trace(shell, lg_raw_console_tracer, undefined, #{}). | |||
---- | |||
The arguments are, in order, the trace patterns (the modules or | |||
applications that need to be traced), the tracer module, the tracer | |||
options, and the Looking Glass options. | |||
=== Tracing to file | |||
Looking Glass comes with a tracer that saves all events directly | |||
into a compressed file. Trace files can be used for replaying events | |||
(for example if you're looking for something specific when debugging) | |||
or for profiling. | |||
Looking Glass compresses the trace files using the LZ4 compression | |||
algorithm. This algorithm was chosen for its very low footprint; | |||
it allows us to reduce the trace file size without putting a strain | |||
on the system being traced. The files produced are compatible with | |||
the LZ4 command line tools. | |||
The options for this tracer are only the filename: | |||
[source,erlang] | |||
---- | |||
1> lg:trace('_', lg_file_tracer, "traces.lz4"). | |||
---- | |||
If you play with the shell a little after running this command, | |||
and then run `lg:stop().` you can see that the following files | |||
have been created: | |||
[source,bash] | |||
---- | |||
$ ls -l traces.lz4.* | |||
-rw-r--r-- 1 essen essen 333676 Feb 28 18:24 traces.lz4.1 | |||
-rw-r--r-- 1 essen essen 384471 Feb 28 18:24 traces.lz4.2 | |||
-rw-r--r-- 1 essen essen 333776 Feb 28 18:24 traces.lz4.3 | |||
-rw-r--r-- 1 essen essen 11689 Feb 28 18:24 traces.lz4.4 | |||
---- | |||
Looking Glass will create one trace file per scheduler by | |||
default (which is typically equal to the number of cores | |||
you have on your machine). The files are split so that | |||
all the events of one process are always stored in the | |||
same file. | |||
We can use the file reader module coming with Looking Glass | |||
to inspect the contents of the files: | |||
[source,erlang] | |||
---- | |||
2> lg_file_reader:foreach(fun(E) -> erlang:display(E) end, "traces.lz4.1"). | |||
{call,<0.51.0>,1488302656982110,{group,io_request,5}} | |||
{call,<0.51.0>,1488302656982114,{group,io_request,4}} | |||
{call,<0.51.0>,1488302656982117,{group,get_tty_geometry,1}} | |||
{call,<0.75.0>,1488302656982129,{file_io_server,io_request,2}} | |||
... | |||
---- | |||
Careful though, don't run this on production either! | |||
Trace files can become really, really big. | |||
You may also write a slightly larger fun to filter what | |||
you want to see, for example all events from a single | |||
process: | |||
[source,erlang] | |||
---- | |||
3> Pid = pid(0,51,0). | |||
<0.51.0> | |||
4> F = fun(E) when element(2, E) =:= Pid -> | |||
erlang:display(E); | |||
(_) -> | |||
ok | |||
end. | |||
#Fun<erl_eval.6.52032458> | |||
5> lg_file_reader:foreach(F, "traces.lz4.1"). | |||
{call,<0.51.0>,1488302656982110,{group,io_request,5}} | |||
{call,<0.51.0>,1488302656982114,{group,io_request,4}} | |||
{call,<0.51.0>,1488302656982117,{group,get_tty_geometry,1}} | |||
{return_to,<0.51.0>,1488302656982306,{group,io_request,4}} | |||
... | |||
---- | |||
=== Tracer mode | |||
When tracing to file for the purposes of profiling, you | |||
most likely do not care about certain events, like processes | |||
being linked. To disable any unnecessary event for profiling, | |||
pass the `mode` option: | |||
[source,erlang] | |||
---- | |||
1> lg:trace('_', lg_file_tracer, "traces.lz4", #{mode => profile}). | |||
---- | |||
[[tracing_running]] | |||
You can also get extra events that are only useful for profiling | |||
by enabling options. The `running` option will enable events | |||
indicating when processes are scheduled in or out. It's generally | |||
useful to have as it enables additional stats, but can take a lot | |||
of resources and so isn't enabled by default: | |||
[source,erlang] | |||
---- | |||
1> lg:trace('_', lg_file_tracer, "traces.lz4", | |||
#{mode => profile, running => true}). | |||
---- | |||
[[tracing_send]] | |||
You may want to also trace the messages sent by the processes. | |||
To do so you need to enable the `send` option. You can then | |||
xref:messages[obtain detailed information about the processes | |||
sending messages]. To enable the tracing of messages: | |||
[source,erlang] | |||
---- | |||
1> lg:trace('_', lg_file_tracer, "traces.lz4", | |||
#{send => true}). | |||
---- | |||
All the options in this section can be combined at will. It is | |||
possible to use the data from the same tracing session when | |||
profiling both functions and messages. | |||
=== Trace file rotation | |||
For long running sessions Looking Glass can rotate trace files. | |||
This is a feature that helps avoid running out of disk space | |||
and is not meant to be for keeping files small (Looking Glass | |||
can deal with very large files just fine). | |||
Instead of passing a filename prefix as a third argument to | |||
`lg:trace/3,4`, a map can be provided. There are currently | |||
three options including the `filename_prefix`. The other options | |||
are the maximum file size in bytes, `max_size`, and the number | |||
of events that will be stored per LZ4 frame in the file, | |||
`events_per_frame`. These two options allow you to control | |||
how often the file will be written to or rotated. | |||
The following example will limit the file sizes to 100MB: | |||
[source,erlang] | |||
---- | |||
1> lg:trace('_', lg_file_tracer, | |||
#{filename_prefix => "traces.lz4", max_size => 100000000}, | |||
#{mode => profile, running => true}). | |||
---- | |||
During testing of this feature it appeared that the rotation | |||
as it's currently implemented is expensive, therefore you | |||
should be careful not to put a value that's too low. |
@ -0,0 +1,11 @@ | |||
{application, eTpf, | |||
[{description, "An OTP application"}, | |||
{vsn, "0.1.0"}, | |||
{registered, []}, | |||
{mod, {eTpf_app, []}}, | |||
{applications, [kernel, stdlib, runtime_tools, lz4]}, | |||
{env, []}, | |||
{modules, []}, | |||
{licenses, ["MIT License"]}, | |||
{links, []} | |||
]}. |
@ -0,0 +1,18 @@ | |||
%%%------------------------------------------------------------------- | |||
%% @doc eTpf public API | |||
%% @end | |||
%%%------------------------------------------------------------------- | |||
-module(eTpf_app). | |||
-behaviour(application). | |||
-export([start/2, stop/1]). | |||
start(_StartType, _StartArgs) -> | |||
eTpf_sup:start_link(). | |||
stop(_State) -> | |||
ok. | |||
%% internal functions |
@ -0,0 +1,35 @@ | |||
%%%------------------------------------------------------------------- | |||
%% @doc eTpf top level supervisor. | |||
%% @end | |||
%%%------------------------------------------------------------------- | |||
-module(eTpf_sup). | |||
-behaviour(supervisor). | |||
-export([start_link/0]). | |||
-export([init/1]). | |||
-define(SERVER, ?MODULE). | |||
start_link() -> | |||
supervisor:start_link({local, ?SERVER}, ?MODULE, []). | |||
%% sup_flags() = #{strategy => strategy(), % optional | |||
%% intensity => non_neg_integer(), % optional | |||
%% period => pos_integer()} % optional | |||
%% child_spec() = #{id => child_id(), % mandatory | |||
%% start => mfargs(), % mandatory | |||
%% restart => restart(), % optional | |||
%% shutdown => shutdown(), % optional | |||
%% type => worker(), % optional | |||
%% modules => modules()} % optional | |||
init([]) -> | |||
SupFlags = #{strategy => one_for_all, | |||
intensity => 0, | |||
period => 1}, | |||
ChildSpecs = [], | |||
{ok, {SupFlags, ChildSpecs}}. | |||
%% internal functions |
@ -0,0 +1,149 @@ | |||
%% Copyright (c) 2017-Present Pivotal Software, Inc. All rights reserved. | |||
%% | |||
%% This package, Looking Glass, is double-licensed under the Mozilla | |||
%% Public License 1.1 ("MPL") and the Apache License version 2 | |||
%% ("ASL"). For the MPL, please see LICENSE-MPL-RabbitMQ. For the ASL, | |||
%% please see LICENSE-APACHE2. | |||
%% | |||
%% This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY KIND, | |||
%% either express or implied. See the LICENSE file for specific language governing | |||
%% rights and limitations of this software. | |||
%% | |||
%% If you have any questions regarding licensing, please contact us at | |||
%% info@rabbitmq.com. | |||
-module(lg). | |||
-export([trace/1]). | |||
-export([trace/2]). | |||
-export([trace/3]). | |||
-export([trace/4]). | |||
-export([stop/0]). | |||
-export([stop/1]). | |||
-type pattern() :: module() | {app, atom()} | {callback, module(), atom()}. | |||
-type scope() :: {scope, [ | |||
pid() | port() | all | processes | ports | | |||
existing | existing_processes | existing_ports | | |||
new | new_processes | new_ports]}. | |||
-type input() :: [pattern() | scope()]. | |||
-export_type([input/0]). | |||
%% The trace functions input is not as strict for user convenience. | |||
-type user_input() :: pattern() | input(). | |||
-type opts() :: #{ | |||
mode => trace | profile, | |||
pool_id => any(), | |||
pool_size => pos_integer(), | |||
send => boolean(), | |||
running => boolean() | |||
}. | |||
-spec trace(user_input()) -> ok. | |||
trace(Input) -> | |||
trace(Input, lg_raw_console_tracer). | |||
-spec trace(user_input(), module()) -> ok. | |||
trace(Input, TracerMod) -> | |||
trace(Input, TracerMod, undefined, #{}). | |||
-spec trace(user_input(), module(), any()) -> ok. | |||
trace(Input, TracerMod, TracerOpts) -> | |||
trace(Input, TracerMod, TracerOpts, #{}). | |||
-spec trace(user_input(), module(), any(), opts()) -> ok. | |||
trace(Input, TracerMod, TracerOpts, Opts) when is_list(Input) -> | |||
do_trace(Input, TracerMod, TracerOpts, Opts); | |||
trace(Input, TracerMod, TracerOpts, Opts) -> | |||
trace([Input], TracerMod, TracerOpts, Opts). | |||
do_trace(Input0, TracerMod, TracerOpts, Opts) -> | |||
%% @todo Remove eventually? | |||
_ = application:ensure_all_started(looking_glass), | |||
%% Start the pool of tracer processes. | |||
PoolID = maps:get(pool_id, Opts, default), | |||
PoolSize = maps:get(pool_size, Opts, erlang:system_info(schedulers)), | |||
true = PoolSize > 0, | |||
{ok, PoolPid} = supervisor:start_child(looking_glass_sup, #{ | |||
id => PoolID, | |||
start => {lg_tracer_pool, start_link, [PoolSize, TracerMod, TracerOpts]}, | |||
restart => temporary, | |||
type => supervisor | |||
}), | |||
Tracers = lg_tracer_pool:tracers(PoolPid), | |||
TracersMap = maps:from_list(lists:zip(lists:seq(0, length(Tracers) - 1), Tracers)), | |||
Mode = maps:get(mode, Opts, trace), | |||
Input1 = flatten(Input0, []), | |||
Input2 = ensure_pattern(Input1), | |||
Input = ensure_scope(Input2), | |||
trace_input(Input, #{mode => Mode, tracers => TracersMap}, Opts), | |||
ok. | |||
flatten([], Acc) -> | |||
lists:flatten(Acc); | |||
flatten([{callback, Mod, Fun}|Tail], Acc) when is_atom(Mod), is_atom(Fun) -> | |||
Input = flatten(Mod:Fun(), []), | |||
flatten(Tail, [Input|Acc]); | |||
flatten([{app, App}|Tail], Acc) when is_atom(App) -> | |||
_ = application:load(App), | |||
{ok, Mods} = application:get_key(App, modules), | |||
flatten(Tail, [Mods|Acc]); | |||
flatten([Input|Tail], Acc) -> | |||
flatten(Tail, [Input|Acc]). | |||
ensure_pattern(Input) -> | |||
case [S || S={scope, _} <- Input] of | |||
Input -> ['_'|Input]; | |||
_ -> Input | |||
end. | |||
ensure_scope(Input) -> | |||
case [S || S={scope, _} <- Input] of | |||
[] -> [{scope, [processes]}|Input]; | |||
_ -> Input | |||
end. | |||
trace_input([], _, _) -> | |||
ok; | |||
trace_input([{scope, Scope}|Tail], TracerState, Opts) -> | |||
%% We currently enable the following trace flags: | |||
%% - call: function calls | |||
%% - procs: process exit events; plus others we ignore | |||
%% - running: process being scheduled in/out | |||
%% - timestamp: events include the current timestamp | |||
%% - arity: function calls only include the arity, not arguments | |||
%% - return_to: return from functions | |||
%% - set_on_spawn: propagate trace flags to any children processes | |||
%% | |||
%% @todo It might be useful to count the number of sends | |||
%% or receives a function does. | |||
ExtraFlags = [running || maps:get(running, Opts, false)] | |||
++ [send || maps:get(send, Opts, false)], | |||
_ = [erlang:trace(PidPortSpec, true, [ | |||
call, procs, timestamp, arity, return_to, set_on_spawn, | |||
{tracer, lg_tracer, TracerState} | |||
|ExtraFlags | |||
]) | |||
|| PidPortSpec <- Scope], | |||
trace_input(Tail, TracerState, Opts); | |||
trace_input([Mod|Tail], TracerState, Opts) when is_atom(Mod) -> | |||
MatchSpec = case Opts of | |||
#{process_dump := true} -> [{'_', [], [{message, {process_dump}}]}]; | |||
_ -> true | |||
end, | |||
%% The module must be loaded before we attempt to trace it. | |||
_ = code:ensure_loaded(Mod), | |||
_ = erlang:trace_pattern({Mod, '_', '_'}, MatchSpec, [local]), | |||
trace_input(Tail, TracerState, Opts). | |||
stop() -> | |||
stop(default). | |||
%% @todo Confirm that we don't need to stop tracing, | |||
%% that just terminating the tracers is enough. The | |||
%% NIF does cancel traces when tracers go away, but | |||
%% better make sure. | |||
stop(PoolID) -> | |||
supervisor:terminate_child(looking_glass_sup, PoolID). |
@ -0,0 +1,512 @@ | |||
%% Copyright (c) 2017-Present Pivotal Software, Inc. All rights reserved. | |||
%% | |||
%% This package, Looking Glass, is double-licensed under the Mozilla | |||
%% Public License 1.1 ("MPL") and the Apache License version 2 | |||
%% ("ASL"). For the MPL, please see LICENSE-MPL-RabbitMQ. For the ASL, | |||
%% please see LICENSE-APACHE2. | |||
%% | |||
%% This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY KIND, | |||
%% either express or implied. See the LICENSE file for specific language governing | |||
%% rights and limitations of this software. | |||
%% | |||
%% If you have any questions regarding licensing, please contact us at | |||
%% info@rabbitmq.com. | |||
-module(lg_callgrind). | |||
-export([patterns/0]). | |||
-export([profile/2]). | |||
-export([profile/3]). | |||
-export([profile_many/2]). | |||
-export([profile_many/3]). | |||
%% @todo Add an option with a list of modules to exclude. | |||
-type opts() :: #{ | |||
%% Whether we filter the output per process. | |||
scope => global | per_process, | |||
%% Whether we compute and save wait times. | |||
running => boolean() | |||
}. | |||
-record(call, { | |||
%% The MFA for the call. | |||
mfa :: atom(), | |||
%% The source file name. | |||
source :: {string(), pos_integer()}, | |||
%% The timestamp for the call. | |||
ts :: pos_integer(), | |||
%% The timestamp for when we last started executing this function. | |||
self_ts :: pos_integer(), | |||
%% Execution time including subcalls. | |||
incl :: undefined | non_neg_integer(), | |||
%% Execution time excluding subcalls. | |||
self = 0 :: integer(), | |||
%% Number of times the function was called. | |||
count = 1 :: pos_integer(), | |||
%% Time when the process was not running in this function. | |||
wait = 0 :: non_neg_integer(), | |||
%% Time when the process was not running in this function or any subcalls. | |||
wait_incl = 0 :: non_neg_integer(), | |||
%% Number of times the process was scheduled out. | |||
wait_count = 0 :: non_neg_integer(), | |||
%% Number of times the function or any subcall was scheduled out. | |||
wait_count_incl = 0 :: non_neg_integer(), | |||
%% Calls done by this MFA. | |||
calls = #{} :: #{atom() => #call{}} | |||
}). | |||
-record(proc, { | |||
%% Call stack. | |||
stack = [] :: [#call{}], | |||
%% Profile information waiting to be written to file. | |||
mfas = #{} :: #{atom() => #call{}}, | |||
%% Timestamp the process got scheduled out. | |||
out = undefined :: undefined | non_neg_integer() | |||
}). | |||
-record(state, { | |||
%% Input file name. | |||
input :: file:filename_all(), | |||
%% Output file name. | |||
output :: file:filename_all(), | |||
%% Output fd. | |||
output_device :: file:io_device(), | |||
%% Options. | |||
opts :: opts(), | |||
%% List of processes. | |||
processes = #{} :: #{pid() => #proc{}}, | |||
%% Cache of source file information. | |||
sources = #{} :: #{mfa() => {string(), pos_integer()}} | |||
}). | |||
-spec patterns() -> lg:input(). | |||
patterns() -> | |||
[{app, kernel}, {app, stdlib}, {app, looking_glass}]. | |||
-spec profile(file:filename_all(), file:filename_all()) -> ok. | |||
profile(Input, Output) -> | |||
profile(Input, Output, #{}). | |||
-spec profile(file:filename_all(), file:filename_all(), opts()) -> ok. | |||
profile(Input, Output, Opts) -> | |||
{ok, OutDevice} = file:open(Output, [write]), | |||
State = #state{input=Input, output=Output, output_device=OutDevice, opts=Opts}, | |||
write_header(State), | |||
{ok, FinalState} = lg_file_reader:fold(fun handle_event/2, State, Input), | |||
flush(FinalState), | |||
_ = file:close(OutDevice), | |||
ok. | |||
flush(State=#state{processes=Procs}) -> | |||
maps:fold(fun(Pid, #proc{mfas=MFAs}, _) -> | |||
write_mfas(Pid, MFAs, State) | |||
end, undefined, Procs), | |||
ok. | |||
-spec profile_many(file:filename(), file:filename()) -> ok. | |||
profile_many(Wildcard, Prefix) -> | |||
profile_many(Wildcard, Prefix, #{}). | |||
-spec profile_many(file:filename(), file:filename(), opts()) -> ok. | |||
profile_many(Wildcard, Prefix, Opts) -> | |||
Files = filelib:wildcard(Wildcard), | |||
Seq = lists:seq(1, length(Files)), | |||
OutFiles = [Prefix ++ "." ++ integer_to_list(N) || N <- Seq], | |||
Many = lists:zip(Files, OutFiles), | |||
Refs = [monitor(process, spawn_link(?MODULE, profile, [Input, Output, Opts])) | |||
|| {Input, Output} <- Many], | |||
wait_for_procs(Refs). | |||
%% We do not need to worry about failure because we are linked. | |||
wait_for_procs([]) -> | |||
ok; | |||
wait_for_procs(Refs) -> | |||
receive | |||
%% We purposefully ignore any stray messages. | |||
{'DOWN', R, process, _, _} -> | |||
wait_for_procs(Refs -- [R]) | |||
end. | |||
%% We handle trace events one by one, keeping track of the | |||
%% execution stack for each process. | |||
%% We don't care about match spec results for callgrind. | |||
handle_event({call, Pid, Ts, MFA, _MSpec}, State) -> | |||
handle_event({call, Pid, Ts, MFA}, State); | |||
handle_event({call, Pid, Ts, MFA}, State0) -> | |||
Proc = case is_process_profiled(Pid, State0) of | |||
{true, P} -> P; | |||
{empty, P} -> P; | |||
false -> #proc{} | |||
end, | |||
{Source, State} = find_source(MFA, State0), | |||
handle_call(Pid, convert_mfa(MFA), Source, Ts, Proc, State); | |||
handle_event({return_to, Pid, Ts, MFA}, State) -> | |||
case is_process_profiled(Pid, State) of | |||
{true, Proc} -> handle_return_to(Pid, convert_mfa(MFA), Ts, Proc, State); | |||
_ -> State | |||
end; | |||
%% Process exited. Unfold the stacktrace entirely. | |||
%% | |||
%% We use the atom exit because we know it will not match | |||
%% a function call and will therefore unfold everything. | |||
handle_event({exit, Pid, Ts, _Reason}, State0) -> | |||
case is_process_profiled(Pid, State0) of | |||
{true, Proc} -> | |||
State=#state{processes=Procs} = handle_return_to(Pid, exit, Ts, Proc, State0), | |||
%% Remove the pid from the state to save memory. | |||
State#state{processes=maps:remove(Pid, Procs)}; | |||
_ -> | |||
State0 | |||
end; | |||
handle_event({in, Pid, Ts, _MFA}, State=#state{opts=#{running := true}}) -> | |||
case is_process_profiled(Pid, State) of | |||
{true, Proc} -> handle_in(Pid, Ts, Proc, State); | |||
_ -> State | |||
end; | |||
handle_event({out, Pid, Ts, _MFA}, State=#state{opts=#{running := true}}) -> | |||
case is_process_profiled(Pid, State) of | |||
{true, Proc} -> handle_out(Pid, Ts, Proc, State); | |||
_ -> State | |||
end; | |||
%% Ignore all other events. We do not need them for building the callgrind file. | |||
handle_event(_, State) -> | |||
State. | |||
is_process_profiled(Pid, #state{processes=Procs}) -> | |||
case maps:get(Pid, Procs, undefined) of | |||
%% We never received events for this process. Ignore. | |||
undefined -> false; | |||
%% We received events but are not in a known function currently. Ignore. | |||
Proc=#proc{stack=[]} -> {empty, Proc}; | |||
%% All good! | |||
Proc -> {true, Proc} | |||
end. | |||
%% We track a number of different things: | |||
%% - how much time was spent in the different function calls | |||
%% - how much time they spent calling other functions | |||
%% - how many times functions were called | |||
%% | |||
%% We track everything on a per process basis. For each process, | |||
%% we maintain a call stack. Every time a function return, we may | |||
%% end up saving call information to the 'mfas' map. We then write | |||
%% this information to the disk whenever the stacktrace becomes | |||
%% empty, or when the process terminates. | |||
%% When we receive a call event, we add the call information | |||
%% to the stack, regardless of what it already contains. | |||
%% This means that recursive calls, whether tail or body, | |||
%% will appear multiple times in the stack. And since Erlang | |||
%% doesn't have loops, it will appear a little weird if | |||
%% compared to an imperative language. | |||
%% Recursive call. Just increase the call count. | |||
handle_call(Pid, MFA, _Source, _Ts, | |||
Proc0=#proc{stack=[Call=#call{mfa=MFA, count=Count}|Stack0]}, | |||
State=#state{processes=Procs}) -> | |||
Stack = [Call#call{count=Count + 1}|Stack0], | |||
Proc = Proc0#proc{stack=Stack}, | |||
State#state{processes=Procs#{Pid => Proc}}; | |||
%% Non-recursive call. | |||
handle_call(Pid, MFA, Source, Ts, Proc0=#proc{stack=Stack0}, | |||
State=#state{processes=Procs}) -> | |||
Stack = [#call{mfa=MFA, source=Source, ts=Ts, self_ts=Ts}|Stack0], | |||
Proc = Proc0#proc{stack=Stack}, | |||
State#state{processes=Procs#{Pid => Proc}}. | |||
%% We return from the current call, so the current call | |||
%% ends regardless of what it was doing. We stop as soon | |||
%% as we see the caller we return to; or if we return all | |||
%% the way up, higher than where we started (for example | |||
%% because we were not tracing the function we actually | |||
%% end up returning to), we get everything. | |||
%% | |||
%% The current call started when it was called and stopped | |||
%% on the return_to timestamp. Therefore it is fairly simple | |||
%% to calculate its incl/self times. | |||
%% | |||
%% Other calls returning at the same time are tail calls. | |||
%% In their case, the incl time is the same as for the | |||
%% current call. However the self time must not stop when | |||
%% returning but rather when doing the final tail call. | |||
%% We also update sub call times since those must be | |||
%% maintained separately. | |||
%% | |||
%% NOTE: Due to how the VM works, if a function has both | |||
%% tail and non-tail calls, it becomes impossible to know | |||
%% what is or is not a tail call, and therefore values | |||
%% may be wrong. Do not write such functions! For example: | |||
%% | |||
%% a(true) -> 1 + b(); a(false) -> b(). | |||
%% | |||
%% Finally we must also update the self for the call we | |||
%% actually return to. In its case we use the time we | |||
%% were last executing the function as a start point, | |||
%% and the return time for the end. Here again we also | |||
%% update the sub call times. | |||
handle_return_to(Pid, MFA, Ts, Proc0=#proc{stack=[Current0|Stack0], mfas=MFAs0}, | |||
State=#state{processes=Procs}) -> | |||
{Returned0, Stack1} = lists:splitwith( | |||
fun(#call{mfa=E}) -> E =/= MFA end, | |||
Stack0), | |||
#call{ts=CurrentTs, self_ts=CurrentSelfTs, self=CurrentSelf} = Current0, | |||
Current = Current0#call{incl=Ts - CurrentTs, self=CurrentSelf + Ts - CurrentSelfTs}, | |||
Returned = update_tail_calls([Current|Returned0], Ts), | |||
Stack = update_stack(Returned, Stack1, Ts), | |||
%% Save the profile information in the state, potentially flushing it | |||
%% to disk if the stack is empty. | |||
MFAs1 = update_mfas(Returned, MFAs0), | |||
MFAs = case Stack of | |||
[] -> | |||
write_mfas(Pid, MFAs1, State), | |||
#{}; | |||
_ -> | |||
MFAs1 | |||
end, | |||
Proc = Proc0#proc{stack=Stack, mfas=MFAs}, | |||
State#state{processes=Procs#{Pid => Proc}}. | |||
update_tail_calls([Call], _) -> | |||
[Call]; | |||
update_tail_calls([ | |||
Callee=#call{ts=CalleeTs}, | |||
Caller0=#call{ts=CallerTs, self_ts=CallerSelfTs, self=CallerSelf} | |||
|Tail], ReturnToTs) -> | |||
Caller1 = Caller0#call{ | |||
incl=ReturnToTs - CallerTs, | |||
self=CallerSelf + CalleeTs - CallerSelfTs | |||
}, | |||
Caller = update_sub_calls(Callee, Caller1), | |||
[Callee|update_tail_calls([Caller|Tail], ReturnToTs)]. | |||
%% Update nothing; there's nothing in the stack. | |||
update_stack(_, [], _) -> | |||
[]; | |||
%% Update the incl/self value based on the top-level function we return from, | |||
%% but only update the sub calls based on the function we directly called. | |||
update_stack(Returned, | |||
[Caller0=#call{self_ts=CallerSelfTs, self=CallerSelf}|Stack], | |||
ReturnToTs) -> | |||
Callee = #call{ts=CalleeTs} = hd(lists:reverse(Returned)), | |||
Caller = Caller0#call{ | |||
self_ts=ReturnToTs, | |||
self=CallerSelf + CalleeTs - CallerSelfTs | |||
}, | |||
[update_sub_calls(Callee, Caller)|Stack]. | |||
update_sub_calls(Callee=#call{mfa=MFA, incl=CallerIncl, count=CallerCount, | |||
wait_incl=CallerWaitIncl}, Caller=#call{calls=SubCalls}) -> | |||
case maps:get(MFA, SubCalls, undefined) of | |||
%% Add the callee to the subcalls but remove the callee's subcalls | |||
%% since we don't need those here. | |||
undefined -> | |||
Caller#call{calls=SubCalls#{MFA => Callee#call{calls=#{}}}}; | |||
%% Same as above, except we add to the existing values. | |||
Sub = #call{incl=SubIncl, count=SubCount, wait_incl=SubWaitIncl} -> | |||
Caller#call{calls=SubCalls#{MFA => Sub#call{ | |||
%% We do not care about self/wait here as we will be using incl/wait_incl in the output. | |||
incl=SubIncl + CallerIncl, | |||
count=SubCount + CallerCount, | |||
wait_incl=SubWaitIncl + CallerWaitIncl | |||
}}} | |||
end. | |||
%% Processes get scheduled in and out. We get the corresponding | |||
%% in and out events when the 'running' option is set to true. | |||
%% We keep track of how many times the process was scheduled out | |||
%% per function, and how long. | |||
handle_in(Pid, InTs, Proc0=#proc{stack=[Current0|Stack0], out=OutTs}, | |||
State=#state{processes=Procs}) -> | |||
#call{wait=Wait, wait_incl=WaitIncl, | |||
wait_count=WaitCount, wait_count_incl=WaitCountIncl | |||
} = Current0, | |||
ThisWait = InTs - OutTs, | |||
%% We increase the wait time for self first. | |||
Current = Current0#call{wait=Wait + ThisWait, wait_incl=WaitIncl + ThisWait, | |||
wait_count=WaitCount + 1, wait_count_incl=WaitCountIncl + 1}, | |||
%% And then for the parent calls to include wait time of subcalls. | |||
Stack = [ | |||
Call#call{wait_incl=ParentWaitIncl + ThisWait, wait_count_incl=ParentWaitCount + 1} | |||
|| Call=#call{wait_incl=ParentWaitIncl, wait_count_incl=ParentWaitCount} <- Stack0], | |||
Proc = Proc0#proc{stack=[Current|Stack], out=undefined}, | |||
State#state{processes=Procs#{Pid => Proc}}. | |||
handle_out(Pid, Ts, Proc0=#proc{out=undefined}, | |||
State=#state{processes=Procs}) -> | |||
Proc = Proc0#proc{out=Ts}, | |||
State#state{processes=Procs#{Pid => Proc}}. | |||
%% Update the profiling information we currently hold. | |||
update_mfas([], MFAs) -> | |||
MFAs; | |||
update_mfas([Call=#call{mfa=MFA, incl=Incl, self=Self, wait=Wait, wait_incl=WaitIncl, | |||
wait_count=WaitCount, wait_count_incl=WaitCountIncl, | |||
count=Count, calls=SubCalls}|Tail], MFAs) -> | |||
case MFAs of | |||
#{MFA := AggCall0=#call{incl=AggIncl, self=AggSelf, wait=AggWait, wait_incl=AggWaitIncl, | |||
wait_count=AggWaitCount, wait_count_incl=AggWaitCountIncl, | |||
count=AggCount, calls=AggSubCalls0}} -> | |||
AggSubCalls = update_mfas(maps:values(SubCalls), AggSubCalls0), | |||
AggCall=AggCall0#call{incl=Incl + AggIncl, self=Self + AggSelf, | |||
wait=Wait + AggWait, wait_incl=WaitIncl + AggWaitIncl, | |||
wait_count=WaitCount + AggWaitCount, | |||
wait_count_incl=WaitCountIncl + AggWaitCountIncl, | |||
count=Count + AggCount, calls=AggSubCalls}, | |||
update_mfas(Tail, MFAs#{MFA => AggCall}); | |||
_ -> | |||
update_mfas(Tail, MFAs#{MFA => Call}) | |||
end. | |||
%% The callgrind format is documented at http://valgrind.org/docs/manual/cl-format.html | |||
%% | |||
%% We currently only store the real time spent in the calls | |||
%% (including wait times). | |||
%% | |||
%% The option 'scope' can be used to enable per process tracking. | |||
write_header(#state{output_device=OutDevice, opts=#{running := true}}) -> | |||
ok = file:write(OutDevice, | |||
"# callgrind format\n" | |||
"events: Total Active Wait WaitCount\n" | |||
"event: Total : Total time in microseconds\n" | |||
"event: Active : Active time in microseconds\n" | |||
"event: Wait : Wait time in microseconds (scheduled out)\n" | |||
"event: WaitCount : Number of times the process was scheduled out\n" | |||
"\n"); | |||
write_header(#state{output_device=OutDevice}) -> | |||
ok = file:write(OutDevice, | |||
"# callgrind format\n" | |||
"events: Total\n" | |||
"event: Total : Total time in microseconds\n" | |||
"\n"). | |||
write_mfas(Pid, MFAs, State) -> | |||
_ = [write_call(Pid, Call, State) || Call <- maps:values(MFAs)], | |||
ok. | |||
write_call(Pid, #call{mfa=MFA, source={Source, LN}, self=Self, wait=Wait, | |||
wait_count=WaitCount, calls=Calls0}, | |||
#state{output_device=OutDevice, opts=Opts}) -> | |||
Calls = maps:values(Calls0), | |||
Ob = case Opts of | |||
#{scope := per_process} -> | |||
["ob=", io_lib:write(Pid), "\n"]; | |||
_ -> | |||
[] | |||
end, | |||
RunningCosts = case Opts of | |||
#{running := true} -> | |||
[ | |||
" ", integer_to_list(Self - Wait), | |||
" ", integer_to_list(Wait), | |||
" ", integer_to_list(WaitCount) | |||
]; | |||
_ -> | |||
[] | |||
end, | |||
file:write(OutDevice, [Ob, | |||
"fl=", Source, "\n" | |||
"fn=", atom_to_list(MFA), "\n", | |||
integer_to_list(LN), " ", integer_to_list(Self), RunningCosts, "\n", | |||
format_subcalls(LN, Calls, Opts), | |||
"\n"]). | |||
format_subcalls(_, [], _) -> | |||
[]; | |||
%% @todo We don't need to write the filename for functions in the same module. | |||
%% @todo We also don't want to put the full file name; instead we should remove | |||
%% the prefix (path to the release). | |||
%% | |||
%% We only look at where the function is defined, we can't really get | |||
%% the actual line number where the call happened, unfortunately. | |||
format_subcalls(LN, [#call{mfa=MFA, source={Source, TargetLN}, incl=Incl, | |||
wait_incl=Wait, wait_count_incl=WaitCount, count=Count, calls=_Calls}|Tail], Opts) -> | |||
RunningCosts = case Opts of | |||
#{running := true} -> | |||
[ | |||
" ", integer_to_list(Incl - Wait), | |||
" ", integer_to_list(Wait), | |||
" ", integer_to_list(WaitCount) | |||
]; | |||
_ -> | |||
[] | |||
end, | |||
[[ | |||
"cfi=", Source, "\n" | |||
"cfn=", atom_to_list(MFA), "\n" | |||
"calls=", integer_to_list(Count), " ", integer_to_list(TargetLN), "\n", | |||
integer_to_list(LN), " ", integer_to_list(Incl), RunningCosts, "\n" | |||
]|format_subcalls(LN, Tail, Opts)]. | |||
convert_mfa(undefined) -> | |||
undefined; | |||
convert_mfa({M0, F0, A0}) -> | |||
M = atom_to_binary(M0, latin1), | |||
F = atom_to_binary(F0, latin1), | |||
A = integer_to_binary(A0), | |||
binary_to_atom(<<M/binary, $:, F/binary, $/, A/binary>>, latin1). | |||
find_source(MFA, State0=#state{sources=Cache}) -> | |||
case Cache of | |||
#{MFA := Source} -> | |||
{Source, State0}; | |||
_ -> | |||
State = #state{sources=#{MFA := Source}} = cache_module(MFA, State0), | |||
{Source, State} | |||
end. | |||
%% We extract the line number of the functions by loading the | |||
%% beam file (which is already loaded when we reach this function) | |||
%% and looking into the abstract code directly. When something | |||
%% goes wrong, for example the module was not compiled with | |||
%% +debug_info, the function will return line number 1. | |||
%% | |||
%% Note that we can only retrieve the location of the function. | |||
%% For functions with many clauses we are not able to properly | |||
%% identify which clause was involved. It's probably a good | |||
%% idea to structure your code to have more functions than | |||
%% function clauses, especially when using behaviours. | |||
%% | |||
%% While this is an expensive operation, we cache the result | |||
%% and therefore this function will only be called once per module. | |||
cache_module(MFA={Module, _, _}, State0=#state{sources=Cache}) -> | |||
try | |||
%% If the module is in the path, we can simply query | |||
%% it for the source file. | |||
Info = Module:module_info(compile), | |||
%% @todo We don't want to return an absolute path, | |||
%% but rather the app/src/file.erl path if it's in | |||
%% an application, or just folder/file.erl if not. | |||
%% This allows different users to point to the | |||
%% same source at different locations on their machine. | |||
{_, Src} = lists:keyfind(source, 1, Info), | |||
cache_module(MFA, State0, Src) | |||
catch _:_ -> | |||
%% Either the module was not found, or it doesn't | |||
%% have a 'source' key in the compile info. | |||
%% | |||
%% We can't cache the module; on the other hand | |||
%% we can cache the result of this operation. | |||
%% Just append .erl to the module name and set the | |||
%% line number to 1, which is of course incorrect. | |||
State0#state{sources=Cache#{MFA => {atom_to_list(Module) ++ ".erl", 1}}} | |||
end. | |||
cache_module(MFA={Module, _, _}, State=#state{sources=Cache0}, Src) -> | |||
{Module, Beam, _} = code:get_object_code(Module), | |||
{ok, {Module, Chunks}} = beam_lib:chunks(Beam, [abstract_code]), | |||
[{abstract_code, {raw_abstract_v1, Forms}}] = Chunks, | |||
Funcs = [{{Module, F, A}, LN} || {function, LN, F, A, _} <- Forms], | |||
Cache1 = lists:foldl(fun({Key, LN}, Acc) -> Acc#{Key => {Src, LN}} end, Cache0, Funcs), | |||
%% We cannot currently retrieve line number information | |||
%% for list comprehensions and funs. We therefore | |||
%% cache the correct file with line number set to 1. | |||
Cache = case Cache1 of | |||
#{MFA := _} -> Cache1; | |||
_ -> Cache1#{MFA => {Src, 1}} | |||
end, | |||
State#state{sources=Cache}. |
@ -0,0 +1,106 @@ | |||
%% Copyright (c) 2017-Present Pivotal Software, Inc. All rights reserved. | |||
%% | |||
%% This package, Looking Glass, is double-licensed under the Mozilla | |||
%% Public License 1.1 ("MPL") and the Apache License version 2 | |||
%% ("ASL"). For the MPL, please see LICENSE-MPL-RabbitMQ. For the ASL, | |||
%% please see LICENSE-APACHE2. | |||
%% | |||
%% This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY KIND, | |||
%% either express or implied. See the LICENSE file for specific language governing | |||
%% rights and limitations of this software. | |||
%% | |||
%% If you have any questions regarding licensing, please contact us at | |||
%% info@rabbitmq.com. | |||
-module(lg_file_reader). | |||
-export([fold/3]). | |||
-export([foreach/2]). | |||
-export([open/1]). | |||
-export([read_event/1]). | |||
-export([close/1]). | |||
-record(state, { | |||
io_device :: file:io_device(), | |||
ctx :: lz4f:dctx(), | |||
buffer = <<>> :: binary(), | |||
offset = 0 :: non_neg_integer(), | |||
uncompressed_offset = 0 :: non_neg_integer() | |||
}). | |||
%% High level API. | |||
fold(Fun, Acc, Filename) -> | |||
{ok, IoDevice} = open(Filename), | |||
Ctx = lz4f:create_decompression_context(), | |||
Ret = fold1(#state{io_device=IoDevice, ctx=Ctx}, Fun, Acc), | |||
ok = close(IoDevice), | |||
Ret. | |||
fold1(State0, Fun, Acc0) -> | |||
case read_event(State0) of | |||
{ok, Event, State} -> | |||
Acc = Fun(Event, Acc0), | |||
fold1(State, Fun, Acc); | |||
eof -> | |||
{ok, Acc0}; | |||
Error = {error, _, _} -> | |||
Error | |||
end. | |||
foreach(Fun, Filename) -> | |||
{ok, IoDevice} = open(Filename), | |||
Ctx = lz4f:create_decompression_context(), | |||
Ret = foreach1(#state{io_device=IoDevice, ctx=Ctx}, Fun), | |||
ok = close(IoDevice), | |||
Ret. | |||
foreach1(State0, Fun) -> | |||
case read_event(State0) of | |||
{ok, Event, State} -> | |||
_ = Fun(Event), | |||
foreach1(State, Fun); | |||
eof -> | |||
ok; | |||
Error = {error, _, _} -> | |||
Error | |||
end. | |||
%% Low level API. | |||
open(Filename) -> | |||
file:open(Filename, [read, binary]). | |||
read_event(State=#state{buffer=Buffer}) -> | |||
case Buffer of | |||
<<Size:32, Bin:Size/binary, Rest/bits>> -> | |||
convert_event_body(State#state{buffer=Rest}, Bin); | |||
_ -> | |||
read_file(State) | |||
end. | |||
read_file(State=#state{io_device=IoDevice, ctx=Ctx, buffer=Buffer, offset=Offset}) -> | |||
case file:read(IoDevice, 1000) of | |||
{ok, Data0} -> | |||
Data = iolist_to_binary(lz4f:decompress(Ctx, Data0)), | |||
read_event(State#state{buffer= <<Buffer/binary, Data/binary>>, | |||
offset=Offset + byte_size(Data0)}); | |||
eof -> | |||
eof; | |||
{error, Reason} -> | |||
{error, Reason, | |||
'An error occurred while trying to read from the file.'} | |||
end. | |||
convert_event_body(State=#state{offset=Offset, uncompressed_offset=UnOffset}, Bin) -> | |||
try binary_to_term(Bin) of | |||
Term -> | |||
{ok, Term, State#state{uncompressed_offset=UnOffset + byte_size(Bin)}} | |||
catch Class:Reason -> | |||
{error, {crash, Class, Reason, Offset, UnOffset}, | |||
'The binary form of an event could not be decoded to an Erlang term.'} | |||
end. | |||
close(IoDevice) -> | |||
file:close(IoDevice). |
@ -0,0 +1,101 @@ | |||
%% Copyright (c) 2017-Present Pivotal Software, Inc. All rights reserved. | |||
%% | |||
%% This package, Looking Glass, is double-licensed under the Mozilla | |||
%% Public License 1.1 ("MPL") and the Apache License version 2 | |||
%% ("ASL"). For the MPL, please see LICENSE-MPL-RabbitMQ. For the ASL, | |||
%% please see LICENSE-APACHE2. | |||
%% | |||
%% This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY KIND, | |||
%% either express or implied. See the LICENSE file for specific language governing | |||
%% rights and limitations of this software. | |||
%% | |||
%% If you have any questions regarding licensing, please contact us at | |||
%% info@rabbitmq.com. | |||
-module(lg_file_tracer). | |||
-export([start_link/2]). | |||
-export([init/3]). | |||
-export([system_continue/3]). | |||
-export([system_terminate/4]). | |||
-export([system_code_change/4]). | |||
-record(state, { | |||
parent :: pid(), | |||
filename :: file:filename_all(), | |||
size = 0 :: non_neg_integer(), | |||
max_size :: infinity | non_neg_integer(), | |||
io_device :: file:io_device(), | |||
events_per_frame :: pos_integer(), | |||
events_this_frame = 0 :: non_neg_integer(), | |||
buffer = <<>> :: binary() | |||
}). | |||
start_link(Nth, Prefix) when is_list(Prefix) -> | |||
start_link(Nth, #{filename_prefix => Prefix}); | |||
start_link(Nth, Opts) when is_map(Opts) -> | |||
Pid = proc_lib:spawn_link(?MODULE, init, [self(), Nth, Opts]), | |||
{ok, Pid}. | |||
init(Parent, Nth, Opts) -> | |||
%% Store all messages off the heap to avoid unnecessary GC. | |||
process_flag(message_queue_data, off_heap), | |||
%% We need to trap exit signals in order to shutdown properly. | |||
process_flag(trap_exit, true), | |||
%% No need to close the file, it'll be closed when the process exits. | |||
Filename = filename:flatten([ | |||
maps:get(filename_prefix, Opts, "traces.lz4"), | |||
".", integer_to_list(Nth)]), | |||
{ok, IoDevice} = file:open(Filename, [write, raw]), | |||
loop(#state{parent=Parent, filename=Filename, io_device=IoDevice, | |||
max_size=maps:get(max_size, Opts, infinity), | |||
events_per_frame=maps:get(events_per_frame, Opts, 100000)}). | |||
loop(State=#state{parent=Parent, size=Size, io_device=IoDevice, | |||
events_per_frame=MaxEvents, events_this_frame=NumEvents0, buffer=Buffer0}) -> | |||
receive | |||
{'EXIT', Parent, Reason} -> | |||
terminate(Reason, State); | |||
{system, From, Request} -> | |||
sys:handle_system_msg(Request, From, Parent, ?MODULE, [], State); | |||
Msg0 -> | |||
Msg = lg_term:truncate(Msg0), | |||
Bin = term_to_binary(Msg), | |||
BinSize = byte_size(Bin), | |||
Buffer = <<Buffer0/binary, BinSize:32, Bin/binary>>, | |||
NumEvents = NumEvents0 + 1, | |||
if | |||
MaxEvents =:= NumEvents -> | |||
Frame = lz4f:compress_frame(Buffer), | |||
ok = file:write(IoDevice, Frame), | |||
maybe_rotate(State#state{size=Size + byte_size(Frame), | |||
events_this_frame=0, buffer= <<>>}); | |||
true -> | |||
loop(State#state{events_this_frame=NumEvents, buffer=Buffer}) | |||
end | |||
end. | |||
maybe_rotate(State=#state{filename=Filename, size=Size, max_size=MaxSize, | |||
io_device=OldIoDevice}) when Size > MaxSize -> | |||
ok = file:close(OldIoDevice), | |||
ok = file:rename(Filename, Filename ++ ".bak"), | |||
{ok, NewIoDevice} = file:open(Filename, [write, raw]), | |||
loop(State#state{size=0, io_device=NewIoDevice}); | |||
maybe_rotate(State) -> | |||
loop(State). | |||
system_continue(_, _, State) -> | |||
loop(State). | |||
-spec system_terminate(any(), _, _, #state{}) -> no_return(). | |||
system_terminate(Reason, _, _, State) -> | |||
terminate(Reason, State). | |||
system_code_change(Misc, _, _, _) -> | |||
{ok, Misc}. | |||
-spec terminate(any(), #state{}) -> no_return(). | |||
terminate(Reason, #state{io_device=IoDevice, buffer=Buffer}) -> | |||
_ = file:write(IoDevice, lz4f:compress_frame(Buffer)), | |||
exit(Reason). |
@ -0,0 +1,288 @@ | |||
%% Copyright (c) 2017-Present Pivotal Software, Inc. All rights reserved. | |||
%% | |||
%% This package, Looking Glass, is double-licensed under the Mozilla | |||
%% Public License 1.1 ("MPL") and the Apache License version 2 | |||
%% ("ASL"). For the MPL, please see LICENSE-MPL-RabbitMQ. For the ASL, | |||
%% please see LICENSE-APACHE2. | |||
%% | |||
%% This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY KIND, | |||
%% either express or implied. See the LICENSE file for specific language governing | |||
%% rights and limitations of this software. | |||
%% | |||
%% If you have any questions regarding licensing, please contact us at | |||
%% info@rabbitmq.com. | |||
-module(lg_flame). | |||
-export([profile/2]). | |||
-export([profile_many/2]). | |||
-record(state, { | |||
output_path="", | |||
pid, | |||
last_ts, | |||
count=0, | |||
acc=[]}). % per-process state | |||
-spec profile(file:filename_all(), file:filename_all()) -> ok. | |||
profile(Input, Output) -> | |||
InitialState = exp1_init(Output), | |||
{ok, FinalState} = lg_file_reader:fold(fun handle_event/2, InitialState, Input), | |||
flush(FinalState). | |||
-spec profile_many(file:filename(), file:filename()) -> ok. | |||
profile_many(Wildcard, Output) -> | |||
InitialState = exp1_init(Output), | |||
Files = filelib:wildcard(Wildcard), | |||
FinalState = lists:foldl(fun(Input, State0) -> | |||
case lg_file_reader:fold(fun handle_event/2, State0, Input) of | |||
{ok, State} -> | |||
State; | |||
{error, Reason, HumanReadable} -> | |||
io:format("Error ~p while reading ~s:~n~s~n", | |||
[Reason, Input, HumanReadable]), | |||
State0 | |||
end | |||
end, InitialState, Files), | |||
flush(FinalState). | |||
flush(#state{output_path=OutputPath}) -> | |||
PidStates = get(), | |||
{ok, FH} = file:open(OutputPath, [write, raw, binary, delayed_write]), | |||
io:format("\n\nWriting to ~s for ~w processes... ", [OutputPath, length(PidStates)]), | |||
_ = [ | |||
[begin | |||
Pid_str0 = lists:flatten(io_lib:format("~w", [Pid])), | |||
Size = length(Pid_str0), | |||
Pid_str = [$(, lists:sublist(Pid_str0, 2, Size-2), $)], | |||
Time_str = integer_to_list(Time), | |||
file:write(FH, [Pid_str, $;, intersperse($;, lists:reverse(Stack)), 32, Time_str, 10]) | |||
end || {Stack, Time} <- Acc] | |||
|| {Pid, #state{acc=Acc} = _S} <- PidStates], | |||
_ = file:close(FH), | |||
io:format("finished!\n"), | |||
ok. | |||
handle_event({Type, Pid, Ts, Arg}, State) -> | |||
exp1({trace_ts, Pid, Type, Arg, Ts}, State); | |||
handle_event({Type, Pid, Ts, Arg, ExtraOrMspec}, State) -> | |||
exp1({trace_ts, Pid, Type, Arg, ExtraOrMspec, Ts}, State); | |||
handle_event({Type, Pid, Ts, Arg, Extra, Mspec}, State) -> | |||
exp1({trace_ts, Pid, Type, Arg, Extra, Mspec, Ts}, State). | |||
%% Below is Scott L. Fritchie's ISC licensed work with only a handful changes. | |||
exp1_init(OutputPath) -> | |||
#state{output_path=OutputPath}. | |||
exp1(T, #state{output_path=OutputPath} = S) -> | |||
trace_ts = element(1, T), | |||
Pid = element(2, T), | |||
PidState = case erlang:get(Pid) of | |||
undefined -> | |||
io:format("~p ", [Pid]), | |||
#state{output_path=OutputPath}; | |||
SomeState -> | |||
SomeState | |||
end, | |||
NewPidState = exp1_inner(T, PidState), | |||
erlang:put(Pid, NewPidState), | |||
S. | |||
exp1_inner({trace_ts, _Pid, InOut, _MFA, _TS}, #state{last_ts=undefined} = S) | |||
when InOut == in; InOut == out -> | |||
%% in & out, without call context, don't help us | |||
S; | |||
exp1_inner({trace_ts, _Pid, Return, _MFA, _TS}, #state{last_ts=undefined} = S) | |||
when Return == return_from; Return == return_to -> | |||
%% return_from and return_to, without call context, don't help us | |||
S; | |||
exp1_inner({trace_ts, Pid, call, MFA, BIN, TS}, | |||
#state{last_ts=LastTS, acc=Acc, count=Count} = S) -> | |||
try | |||
%% Calculate time elapsed, TS-LastTs. | |||
%% 0. If Acc is empty, then skip step #1. | |||
%% 1. Credit elapsed time to the stack on the top of Acc. | |||
%% 2. Push a 0 usec item with this stack onto Acc. | |||
Stak = lists:filter(fun(<<"unknown function">>) -> false; | |||
(_) -> true | |||
end, stak_binify(BIN)), | |||
Stack0 = stak_trim(Stak), | |||
MFA_bin = mfa_binify(MFA), | |||
Stack1 = [MFA_bin|lists:reverse(Stack0)], | |||
Acc2 = case Acc of | |||
[] -> | |||
[{Stack1, 0}]; | |||
[{LastStack, LastTime}|Tail] -> | |||
USec = TS - LastTS, | |||
% io:format("Stack1: ~p ~p\n", [Stack1, USec]), | |||
[{Stack1, 0}, | |||
{LastStack, LastTime + USec}|Tail] | |||
end, | |||
%% TODO: more state tracking here. | |||
S#state{pid=Pid, last_ts=TS, count=Count+1, acc=Acc2} | |||
catch XX:YY:ZZ -> | |||
io:format(user, "~p: ~p:~p @ ~p\n", [?LINE, XX, YY, ZZ]), | |||
S | |||
end; | |||
exp1_inner({trace_ts, _Pid, return_to, MFA, TS}, #state{last_ts=LastTS, acc=Acc} = S) -> | |||
try | |||
%% Calculate time elapsed, TS-LastTs. | |||
%% 1. Credit elapsed time to the stack on the top of Acc. | |||
%% 2. Push a 0 usec item with the "best" stack onto Acc. | |||
%% "best" = MFA exists in the middle of the stack onto Acc, | |||
%% or else MFA exists at the top of a stack elsewhere in Acc. | |||
[{LastStack, LastTime}|Tail] = Acc, | |||
MFA_bin = mfa_binify(MFA), | |||
BestStack = lists:dropwhile(fun(SomeMFA) when SomeMFA /= MFA_bin -> true; | |||
(_) -> false | |||
end, find_matching_stack(MFA_bin, Acc)), | |||
USec = TS - LastTS, | |||
Acc2 = [{BestStack, 0}, | |||
{LastStack, LastTime + USec}|Tail], | |||
% io:format(user, "return-to: ~p\n", [lists:sublist(Acc2, 4)]), | |||
S#state{last_ts=TS, acc=Acc2} | |||
catch XX:YY:ZZ -> | |||
io:format(user, "~p: ~p:~p @ ~p\n", [?LINE, XX, YY, ZZ]), | |||
S | |||
end; | |||
exp1_inner({trace_ts, _Pid, gc_start, _Info, TS}, #state{last_ts=LastTS, acc=Acc} = S) -> | |||
try | |||
%% Push a 0 usec item onto Acc. | |||
[{LastStack, LastTime}|Tail] = Acc, | |||
NewStack = [<<"GARBAGE-COLLECTION">>|LastStack], | |||
USec = TS - LastTS, | |||
Acc2 = [{NewStack, 0}, | |||
{LastStack, LastTime + USec}|Tail], | |||
% io:format(user, "GC 1: ~p\n", [lists:sublist(Acc2, 4)]), | |||
S#state{last_ts=TS, acc=Acc2} | |||
catch _XX:_YY:_ZZ -> | |||
%% io:format(user, "~p: ~p:~p @ ~p\n", [?LINE, _XX, _YY, _ZZ]), | |||
S | |||
end; | |||
exp1_inner({trace_ts, _Pid, gc_end, _Info, TS}, #state{last_ts=LastTS, acc=Acc} = S) -> | |||
try | |||
%% Push the GC time onto Acc, then push 0 usec item from last exec | |||
%% stack onto Acc. | |||
[{GCStack, GCTime},{LastExecStack,_}|Tail] = Acc, | |||
USec = TS - LastTS, | |||
Acc2 = [{LastExecStack, 0}, {GCStack, GCTime + USec}|Tail], | |||
% io:format(user, "GC 2: ~p\n", [lists:sublist(Acc2, 4)]), | |||
S#state{last_ts=TS, acc=Acc2} | |||
catch _XX:_YY:_ZZ -> | |||
%% io:format(user, "~p: ~p:~p @ ~p\n", [?LINE, _XX, _YY, _ZZ]), | |||
S | |||
end; | |||
exp1_inner({trace_ts, _Pid, out, MFA, TS}, #state{last_ts=LastTS, acc=Acc} = S) -> | |||
try | |||
%% Push a 0 usec item onto Acc. | |||
%% The MFA reported here probably doesn't appear in the stacktrace | |||
%% given to us by the last 'call', so add it here. | |||
[{LastStack, LastTime}|Tail] = Acc, | |||
MFA_bin = mfa_binify(MFA), | |||
NewStack = [<<"SLEEP">>,MFA_bin|LastStack], | |||
USec = TS - LastTS, | |||
Acc2 = [{NewStack, 0}, | |||
{LastStack, LastTime + USec}|Tail], | |||
S#state{last_ts=TS, acc=Acc2} | |||
catch XX:YY:ZZ -> | |||
io:format(user, "~p: ~p:~p @ ~p\n", [?LINE, XX, YY, ZZ]), | |||
S | |||
end; | |||
exp1_inner({trace_ts, _Pid, in, MFA, TS}, #state{last_ts=LastTS, acc=Acc} = S) -> | |||
try | |||
%% Push the Sleep time onto Acc, then push 0 usec item from last | |||
%% exec stack onto Acc. | |||
%% The MFA reported here probably doesn't appear in the stacktrace | |||
%% given to us by the last 'call', so add it here. | |||
MFA_bin = mfa_binify(MFA), | |||
[{SleepStack, SleepTime},{LastExecStack,_}|Tail] = Acc, | |||
USec = TS - LastTS, | |||
Acc2 = [{[MFA_bin|LastExecStack], 0}, {SleepStack, SleepTime + USec}|Tail], | |||
S#state{last_ts=TS, acc=Acc2} | |||
catch XX:YY:ZZ -> | |||
io:format(user, "~p: ~p:~p @ ~p\n", [?LINE, XX, YY, ZZ]), | |||
S | |||
end; | |||
%exp1_inner(end_of_trace = _Else, #state{pid=Pid, output_path=OutputPath, acc=Acc} = S) -> | |||
% {ok, FH} = file:open(OutputPath, [write, raw, binary, delayed_write]), | |||
% io:format("Writing to ~s ... ", [OutputPath]), | |||
% [begin | |||
% Pid_str = io_lib:format("~w", [Pid]), | |||
% Time_str = integer_to_list(Time), | |||
% file:write(FH, [Pid_str, $;, intersperse($;, lists:reverse(Stack)), 32, Time_str, 10]) | |||
% end || {Stack, Time} <- Acc], | |||
% file:close(FH), | |||
% io:format("finished\n"), | |||
% S; | |||
exp1_inner(_Else, S) -> | |||
% io:format("?? ~P\n", [_Else, 10]), | |||
S. | |||
find_matching_stack(MFA_bin, [{H,_Time}|_] = Acc) -> | |||
case lists:member(MFA_bin, H) of | |||
true -> | |||
H; | |||
false -> | |||
find_matching_stack2(MFA_bin, Acc) | |||
end. | |||
find_matching_stack2(MFA_bin, [{[MFA_bin|_StackTail]=Stack,_Time}|_]) -> | |||
Stack; | |||
find_matching_stack2(MFA_bin, [_H|T]) -> | |||
find_matching_stack2(MFA_bin, T); | |||
find_matching_stack2(_MFA_bin, []) -> | |||
[<<"FIND-MATCHING-FAILED">>]. | |||
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% | |||
intersperse(_, []) -> []; | |||
intersperse(_, [X]) -> [X]; | |||
intersperse(Sep, [X | Xs]) -> [X, Sep | intersperse(Sep, Xs)]. | |||
stak_trim([<<"proc_lib:init_p_do_apply/3">>,<<"gen_fsm:decode_msg/9">>,<<"gen_fsm:handle_msg/7">>,<<"gen_fsm:loop/7">>|T]) -> | |||
stak_trim([<<"GEN-FSM">>|T]); | |||
stak_trim([<<"GEN-FSM">>,<<"gen_fsm:decode_msg/9">>,<<"gen_fsm:handle_msg/7">>,<<"gen_fsm:loop/7">>|T]) -> | |||
stak_trim([<<"GEN-FSM">>|T]); | |||
stak_trim(Else) -> | |||
Else. | |||
stak_binify(Bin) when is_binary(Bin) -> | |||
[list_to_binary(X) || X <- stak(Bin)]; | |||
stak_binify(X) -> | |||
list_to_binary(io_lib:format("~w", [X])). | |||
mfa_binify({M,F,A}) -> | |||
list_to_binary(io_lib:format("~w:~w/~w", [M, F, A])); | |||
mfa_binify(X) -> | |||
list_to_binary(io_lib:format("~w", [X])). | |||
%% Borrowed from redbug.erl | |||
stak(Bin) -> | |||
lists:foldl(fun munge/2,[],string:tokens(binary_to_list(Bin),"\n")). | |||
munge(I,Out) -> | |||
case I of %% lists:reverse(I) of | |||
"..."++_ -> ["truncated!!!"|Out]; | |||
_ -> | |||
case string:str(I, "Return addr") of | |||
0 -> | |||
case string:str(I, "cp = ") of | |||
0 -> Out; | |||
_ -> [mfaf(I)|Out] | |||
end; | |||
_ -> | |||
case string:str(I, "erminate process normal") of | |||
0 -> [mfaf(I)|Out]; | |||
_ -> Out | |||
end | |||
end | |||
end. | |||
mfaf(I) -> | |||
[_, C|_] = string:tokens(I,"()+"), | |||
string:strip(C). |
@ -0,0 +1,214 @@ | |||
%% Copyright (c) 2017-Present Pivotal Software, Inc. All rights reserved. | |||
%% | |||
%% This package, Looking Glass, is double-licensed under the Mozilla | |||
%% Public License 1.1 ("MPL") and the Apache License version 2 | |||
%% ("ASL"). For the MPL, please see LICENSE-MPL-RabbitMQ. For the ASL, | |||
%% please see LICENSE-APACHE2. | |||
%% | |||
%% This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY KIND, | |||
%% either express or implied. See the LICENSE file for specific language governing | |||
%% rights and limitations of this software. | |||
%% | |||
%% If you have any questions regarding licensing, please contact us at | |||
%% info@rabbitmq.com. | |||
-module(lg_messages). | |||
-export([profile/1]). | |||
-export([profile_many/1]). | |||
-record(state, { | |||
meta = #{} :: map(), | |||
senders = #{} :: #{pid() => pos_integer()}, | |||
receivers = #{} :: #{pid() => pos_integer()}, | |||
pairs = #{} :: #{{pid(), pid()} => pos_integer()}, | |||
non_existing = #{} :: #{pid() => pos_integer()}, | |||
last_msgs = #{} :: #{pid() => atom()} | |||
}). | |||
-spec profile(file:filename_all()) -> ok. | |||
profile(Input) -> | |||
{ok, FinalState} = lg_file_reader:fold(fun handle_event/2, #state{}, Input), | |||
flush(FinalState). | |||
-spec profile_many(file:filename()) -> ok. | |||
profile_many(Wildcard) -> | |||
Files = filelib:wildcard(Wildcard), | |||
FinalState = lists:foldl(fun(Input, State0) -> | |||
{ok, State} = lg_file_reader:fold(fun handle_event/2, State0, Input), | |||
State | |||
end, #state{}, Files), | |||
flush(FinalState). | |||
%% @todo Later we may want to look at the latency of gen_server call/reply. | |||
%% @todo Later we may want to look at particular messages, have some sort of callback. | |||
handle_event({send, From, _, Info, lg}, State=#state{meta=Meta0}) -> | |||
Meta = case Meta0 of | |||
#{From := Info0} -> Meta0#{From => maps:merge(Info0, Info)}; | |||
_ -> Meta0#{From => Info} | |||
end, | |||
State#state{meta=Meta}; | |||
handle_event({send, From, _, Msg, To}, | |||
State=#state{senders=Senders, receivers=Receivers, pairs=Pairs, last_msgs=Msgs}) -> | |||
SendersCount = maps:get(From, Senders, 0), | |||
ReceiversCount = maps:get(To, Receivers, 0), | |||
PairsCount = maps:get({From, To}, Pairs, 0), | |||
State#state{ | |||
senders=Senders#{From => SendersCount + 1}, | |||
receivers=Receivers#{To => ReceiversCount + 1}, | |||
pairs=Pairs#{{From, To} => PairsCount + 1}, | |||
last_msgs=Msgs#{From => Msg}}; | |||
handle_event({send_to_non_existing_process, From, _, Msg, _}, | |||
State=#state{non_existing=Map, last_msgs=Msgs}) -> | |||
Count = maps:get(From, Map, 0), | |||
State#state{ | |||
non_existing=Map#{From => Count + 1}, | |||
last_msgs=Msgs#{From => Msg}}; | |||
%% Ignore all other events. We only care about messages. | |||
handle_event(_, State) -> | |||
State. | |||
%% Output of the profiling. | |||
flush(State) -> | |||
flush_most_active_senders(State), | |||
flush_most_active_receivers(State), | |||
flush_most_non_existing(State), | |||
flush_most_active_pair_unidirectional(State), | |||
flush_most_active_pair_bidirectional(State), | |||
io:format("~n"), | |||
flush_digraph(State), | |||
ok. | |||
flush_most_active_senders(State=#state{senders=Procs}) -> | |||
List = lists:sublist( | |||
lists:reverse(lists:keysort(2, maps:to_list(Procs))), | |||
1, 100), | |||
format_by_count("They sent the most messages", List, State). | |||
flush_most_active_receivers(State=#state{receivers=Procs}) -> | |||
List = lists:sublist( | |||
lists:reverse(lists:keysort(2, maps:to_list(Procs))), | |||
1, 100), | |||
format_by_count("They received the most messages", List, State). | |||
flush_most_non_existing(State=#state{non_existing=Procs}) -> | |||
List = lists:sublist( | |||
lists:reverse(lists:keysort(2, maps:to_list(Procs))), | |||
1, 100), | |||
format_by_count("They sent the most messages to dead processes", List, State). | |||
format_by_count(Title, List, State) -> | |||
MsgCols = case io:columns() of | |||
{ok, Cols} -> Cols; | |||
_ -> 80 | |||
end, | |||
io:format( | |||
"~n~s~n~s~n~n" | |||
"Process ID Count (Label) OR Message sent~n" | |||
"---------- ----- -----------------------~n", | |||
[Title, lists:duplicate(length(Title), $=)]), | |||
_ = [begin | |||
{Prefix, Label, Suffix} = label_or_msg(P, State), | |||
io:format("~-15w ~-10b ~s~" ++ integer_to_list(MsgCols) ++ "P~s~n", | |||
[P, C, Prefix, Label, 5, Suffix]) | |||
end || {P, C} <- List], | |||
ok. | |||
label_or_msg(P, #state{meta=Meta, last_msgs=Msgs}) -> | |||
case maps:get(P, Meta, #{}) of | |||
#{process_type := PT} -> {"(", PT, ")"}; | |||
_ -> {"", maps:get(P, Msgs, '<none>'), ""} | |||
end. | |||
flush_most_active_pair_unidirectional(State=#state{pairs=Procs}) -> | |||
List = lists:sublist( | |||
lists:reverse(lists:keysort(2, maps:to_list(Procs))), | |||
1, 100), | |||
Title = "They sent the most messages to one other process", | |||
MsgCols = case io:columns() of | |||
{ok, Cols} -> Cols; | |||
_ -> 80 | |||
end, | |||
io:format( | |||
"~n~s~n~s~n~n" | |||
"From pid To pid Count (Label) OR Message sent~n" | |||
"-------- ------ ----- -----------------------~n", | |||
[Title, lists:duplicate(length(Title), $=)]), | |||
_ = [begin | |||
{Prefix, Label, Suffix} = label_or_msg(F, State), | |||
io:format("~-15w ~-15w ~-10b ~s~" ++ integer_to_list(MsgCols) ++ "P~s~n", | |||
[F, T, C, Prefix, Label, 5, Suffix]) | |||
end || {{F, T}, C} <- List], | |||
ok. | |||
flush_most_active_pair_bidirectional(State=#state{pairs=Procs0}) -> | |||
Procs = maps:fold(fun merge_pairs/3, #{}, Procs0), | |||
List = lists:sublist( | |||
lists:reverse(lists:keysort(2, maps:to_list(Procs))), | |||
1, 100), | |||
Title = "They sent the most messages to each other", | |||
MsgCols = case io:columns() of | |||
{ok, Cols} -> Cols; | |||
_ -> 80 | |||
end, | |||
io:format( | |||
"~n~s~n~s~n~n" | |||
"Count Pid 1 (Label) OR Message sent~n" | |||
" Pid 2 by the corresponding process~n" | |||
"----- ----- ----------------------------~n", | |||
[Title, lists:duplicate(length(Title), $=)]), | |||
_ = [begin | |||
{FPrefix, FLabel, FSuffix} = label_or_msg(F, State), | |||
{TPrefix, TLabel, TSuffix} = label_or_msg(T, State), | |||
io:format( | |||
"~-10b ~-15w ~s~" ++ integer_to_list(MsgCols) ++ "P~s~n" | |||
" ~-15w ~s~" ++ integer_to_list(MsgCols) ++ "P~s~n", | |||
[C, F, FPrefix, FLabel, 5, FSuffix, | |||
T, TPrefix, TLabel, 5, TSuffix]) | |||
end || {{F, T}, C} <- List], | |||
ok. | |||
flush_digraph(State=#state{pairs=Procs0}) -> | |||
Procs = maps:fold(fun group_pairs/3, #{}, Procs0), | |||
List = maps:to_list(Procs), | |||
ok = file:write_file("digraph.gv", [ | |||
"digraph {\n" | |||
" concentrate=true;\n" | |||
" splines=ortho;\n" | |||
" edge [arrowhead=none, labelfontsize=12.0, minlen=3];\n" | |||
"\n", | |||
[io_lib:format(" \"~w~s\" -> \"~w~s\" [taillabel=~b, headlabel=~b];~n", | |||
[F, label(F, State), T, label(T, State), FC, TC]) || {{F, T}, {FC, TC}} <- List], | |||
"}\n" | |||
]), | |||
io:format( | |||
"The file digraph.gv was created. Use GraphViz to make a PNG.~n" | |||
"$ dot -Tpng -O digraph.gv~n" | |||
"~n" | |||
"You can also edit the file to remove uninteresting processes.~n" | |||
"One line in the file is equal to a connection between two processes.~n"), | |||
ok. | |||
label(P, #state{meta=Meta}) -> | |||
case maps:get(P, Meta, #{}) of | |||
#{process_type := PT} -> io_lib:format(" (~w)", [PT]); | |||
_ -> "" | |||
end. | |||
merge_pairs({From, To}, Count, Acc) -> | |||
Key = if | |||
From < To -> {From, To}; | |||
true -> {To, From} | |||
end, | |||
AccCount = maps:get(Key, Acc, 0), | |||
Acc#{Key => AccCount + Count}. | |||
group_pairs({From, To}, Count, Acc) when From < To -> | |||
Key = {From, To}, | |||
{_, AccCount} = maps:get(Key, Acc, {0, 0}), | |||
Acc#{Key => {Count, AccCount}}; | |||
group_pairs({From, To}, Count, Acc) -> | |||
Key = {To, From}, | |||
{AccCount, _} = maps:get(Key, Acc, {0, 0}), | |||
Acc#{Key => {AccCount, Count}}. |
@ -0,0 +1,144 @@ | |||
%% Copyright (c) 2017-Present Pivotal Software, Inc. All rights reserved. | |||
%% | |||
%% This package, Looking Glass, is double-licensed under the Mozilla | |||
%% Public License 1.1 ("MPL") and the Apache License version 2 | |||
%% ("ASL"). For the MPL, please see LICENSE-MPL-RabbitMQ. For the ASL, | |||
%% please see LICENSE-APACHE2. | |||
%% | |||
%% This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY KIND, | |||
%% either express or implied. See the LICENSE file for specific language governing | |||
%% rights and limitations of this software. | |||
%% | |||
%% If you have any questions regarding licensing, please contact us at | |||
%% info@rabbitmq.com. | |||
-module(lg_messages_seqdiag). | |||
-export([profile/2]). | |||
-export([profile_many/2]). | |||
-record(state, { | |||
meta = #{} :: map(), | |||
events = [], | |||
pids | |||
}). | |||
-spec profile(file:filename_all(), list()) -> ok. | |||
profile(Input, Pids) -> | |||
{ok, FinalState} = lg_file_reader:fold(fun handle_event/2, | |||
#state{pids=prepare_pids(Pids)}, Input), | |||
flush(FinalState). | |||
-spec profile_many(file:filename(), list()) -> ok. | |||
profile_many(Wildcard, Pids) -> | |||
Files = filelib:wildcard(Wildcard), | |||
FinalState = lists:foldl(fun(Input, State0) -> | |||
{ok, State} = lg_file_reader:fold(fun handle_event/2, State0, Input), | |||
State | |||
end, #state{pids=prepare_pids(Pids)}, Files), | |||
flush(FinalState). | |||
handle_event({send, From, _, Info, lg}, State=#state{meta=Meta0}) -> | |||
Meta = case Meta0 of | |||
#{From := Info0} -> Meta0#{From => maps:merge(Info0, Info)}; | |||
_ -> Meta0#{From => Info} | |||
end, | |||
State#state{meta=Meta}; | |||
handle_event(Event = {Type, From, _, _, To}, State) | |||
when Type =:= send; Type =:= send_to_non_existing_process -> | |||
maybe_keep_event(Event, From, To, State); | |||
handle_event(Event = {spawn, From, _, To, _}, State) -> | |||
maybe_keep_event(Event, From, To, State); | |||
handle_event(Event = {exit, Pid0, _, _}, State=#state{events=Events, pids=Pids}) -> | |||
Pid = hide_pid_node(Pid0), | |||
case lists:member(Pid, Pids) of | |||
true -> State#state{events=[Event|Events]}; | |||
_ -> State | |||
end; | |||
%% Ignore all other events. We only care about messages and spawns/exits. | |||
handle_event(_, State) -> | |||
State. | |||
maybe_keep_event(Event, From0, To0, State=#state{events=Events, pids=Pids}) -> | |||
From = hide_pid_node(From0), | |||
To = hide_pid_node(To0), | |||
case {lists:member(From, Pids), lists:member(To, Pids)} of | |||
{true, true} -> State#state{events=[Event|Events]}; | |||
_ -> State | |||
end. | |||
prepare_pids(Pids) -> | |||
[hide_pid_node(Pid) || Pid <- Pids]. | |||
hide_pid_node(Pid) when is_pid(Pid) -> hide_pid_node(pid_to_list(Pid)); | |||
hide_pid_node([$<, _, $.|Tail]) -> "<***." ++ Tail; | |||
hide_pid_node([$<, _, _, $.|Tail]) -> "<***." ++ Tail; | |||
hide_pid_node([$<, _, _, _, $.|Tail]) -> "<***." ++ Tail; | |||
hide_pid_node([$<, _, _, _, _, $.|Tail]) -> "<***." ++ Tail; | |||
hide_pid_node([$<, _, _, _, _, _, $.|Tail]) -> "<***." ++ Tail; | |||
hide_pid_node(Name) -> Name. | |||
flush(State=#state{events=Events0}) -> | |||
%% Sort by timestamp from oldest to newest. | |||
Events = lists:keysort(3, Events0), | |||
%% Initialize the formatting state. | |||
put(num_calls, 0), | |||
%% Output everything. | |||
ok = file:write_file("seq.diag", [ | |||
"seqdiag {\n" | |||
" edge_length = 300;\n" | |||
" activation = none;\n" | |||
"\n", | |||
[format_event(Event, State) || Event <- Events], | |||
"}\n" | |||
]), | |||
io:format( | |||
"The file seq.diag was created. Use seqdiag to make a PNG.~n" | |||
"$ seqdiag -Tpng --no-transparency seq.diag~n" | |||
"~n" | |||
"To use a custom font, use the -f modifier:~n" | |||
"$ seqdiag -Tpng --no-transparency -f /usr/share/fonts/TTF/verdana.ttf seq.diag~n" | |||
"~n" | |||
"You can also edit the file to remove uninteresting messages.~n" | |||
"One line in the file is equal to a message sent by a process to another.~n"), | |||
ok. | |||
format_event({spawn, From, _, To, MFA}, State) -> | |||
io_lib:format(" \"~w~s\" ->> \"~w~s\" [label=\"spawn ~9999P\"];~n", [ | |||
From, label(From, State), To, label(To, State), MFA, 8]); | |||
format_event({exit, Pid, _, Reason}, State) -> | |||
PidLabel = label(Pid, State), | |||
io_lib:format(" \"~w~s\" ->> \"~w~s\" [label=\"exit ~9999P\"];~n", [ | |||
Pid, PidLabel, Pid, PidLabel, Reason, 8]); | |||
format_event({Type, From, _, {'$gen_call', {From, Ref}, Msg}, To}, State) -> | |||
NumCalls = get(num_calls) + 1, | |||
put(num_calls, NumCalls), | |||
put(Ref, NumCalls), | |||
io_lib:format(" \"~w~s\" ~s \"~w~s\" [label=\"gen:call #~w ~9999P\"];~n", [ | |||
From, label(From, State), | |||
case Type of send -> "->"; _ -> "-->" end, | |||
To, label(To, State), NumCalls, Msg, 8]); | |||
format_event(Event={Type, From, _, {Ref, Msg}, To}, State) -> | |||
case get(Ref) of | |||
undefined -> | |||
default_format_event(Event, State); | |||
NumCall -> | |||
io_lib:format(" \"~w~s\" ~s \"~w~s\" [label=\"#~w ~9999P\"];~n", [ | |||
From, label(From, State), | |||
case Type of send -> "->"; _ -> "-->" end, | |||
To, label(To, State), NumCall, Msg, 8]) | |||
end; | |||
format_event(Event, State) -> | |||
default_format_event(Event, State). | |||
default_format_event({Type, From, _, Msg, To}, State) -> | |||
io_lib:format(" \"~w~s\" ~s \"~w~s\" [label=\"~9999P\"];~n", [ | |||
From, label(From, State), | |||
case Type of send -> "->"; _ -> "-->" end, | |||
To, label(To, State), Msg, 8]). | |||
label(P, #state{meta=Meta}) -> | |||
case maps:get(P, Meta, #{}) of | |||
#{process_type := PT} -> io_lib:format(" (~w)", [PT]); | |||
_ -> "" | |||
end. |
@ -0,0 +1,59 @@ | |||
%% Copyright (c) 2017-Present Pivotal Software, Inc. All rights reserved. | |||
%% | |||
%% This package, Looking Glass, is double-licensed under the Mozilla | |||
%% Public License 1.1 ("MPL") and the Apache License version 2 | |||
%% ("ASL"). For the MPL, please see LICENSE-MPL-RabbitMQ. For the ASL, | |||
%% please see LICENSE-APACHE2. | |||
%% | |||
%% This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY KIND, | |||
%% either express or implied. See the LICENSE file for specific language governing | |||
%% rights and limitations of this software. | |||
%% | |||
%% If you have any questions regarding licensing, please contact us at | |||
%% info@rabbitmq.com. | |||
%% The purpose of this process is to be the target of messages | |||
%% sent by traced processes. The messages contain metadata that | |||
%% we want to log when we are tracing and later use when profiling | |||
%% the sending of messages. This process does not need them, it | |||
%% just needs to exist, and therefore it discards everything. | |||
-module(lg_rabbit_hole). | |||
-behaviour(gen_server). | |||
%% API. | |||
-export([start_link/0]). | |||
%% gen_server. | |||
-export([init/1]). | |||
-export([handle_call/3]). | |||
-export([handle_cast/2]). | |||
-export([handle_info/2]). | |||
-export([terminate/2]). | |||
-export([code_change/3]). | |||
%% API. | |||
-spec start_link() -> {ok, pid()}. | |||
start_link() -> | |||
gen_server:start_link({local, lg}, ?MODULE, [], []). | |||
%% gen_server. | |||
init([]) -> | |||
{ok, undefined}. | |||
handle_call(_Request, _From, State) -> | |||
{reply, ignored, State}. | |||
handle_cast(_Msg, State) -> | |||
{noreply, State}. | |||
handle_info(_Info, State) -> | |||
{noreply, State}. | |||
terminate(_Reason, _State) -> | |||
ok. | |||
code_change(_OldVsn, State, _Extra) -> | |||
{ok, State}. |
@ -0,0 +1,53 @@ | |||
%% Copyright (c) 2017-Present Pivotal Software, Inc. All rights reserved. | |||
%% | |||
%% This package, Looking Glass, is double-licensed under the Mozilla | |||
%% Public License 1.1 ("MPL") and the Apache License version 2 | |||
%% ("ASL"). For the MPL, please see LICENSE-MPL-RabbitMQ. For the ASL, | |||
%% please see LICENSE-APACHE2. | |||
%% | |||
%% This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY KIND, | |||
%% either express or implied. See the LICENSE file for specific language governing | |||
%% rights and limitations of this software. | |||
%% | |||
%% If you have any questions regarding licensing, please contact us at | |||
%% info@rabbitmq.com. | |||
-module(lg_raw_console_tracer). | |||
-export([start_link/2]). | |||
-export([init/1]). | |||
-export([loop/1]). | |||
-export([system_continue/3]). | |||
-export([system_terminate/4]). | |||
-export([system_code_change/4]). | |||
start_link(_Nth, _Opts) -> | |||
Pid = proc_lib:spawn_link(?MODULE, init, [self()]), | |||
{ok, Pid}. | |||
init(Parent) -> | |||
%% Store all messages off the heap to avoid unnecessary GC. | |||
process_flag(message_queue_data, off_heap), | |||
loop(Parent). | |||
loop(Parent) -> | |||
receive | |||
{system, From, Request} -> | |||
sys:handle_system_msg(Request, From, Parent, ?MODULE, [], Parent); | |||
Msg0 -> | |||
%% Convert the event's monotonic time to its system time. | |||
Msg = setelement(3, Msg0, erlang:time_offset(microsecond) + element(3, Msg0)), | |||
erlang:display(Msg), | |||
loop(Parent) | |||
end. | |||
system_continue(_, _, Parent) -> | |||
loop(Parent). | |||
-spec system_terminate(any(), _, _, _) -> no_return(). | |||
system_terminate(Reason, _, _, _) -> | |||
exit(Reason). | |||
system_code_change(Misc, _, _, _) -> | |||
{ok, Misc}. |
@ -0,0 +1,117 @@ | |||
%% Copyright (c) 2017-Present Pivotal Software, Inc. All rights reserved. | |||
%% | |||
%% This package, Looking Glass, is double-licensed under the Mozilla | |||
%% Public License 1.1 ("MPL") and the Apache License version 2 | |||
%% ("ASL"). For the MPL, please see LICENSE-MPL-RabbitMQ. For the ASL, | |||
%% please see LICENSE-APACHE2. | |||
%% | |||
%% This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY KIND, | |||
%% either express or implied. See the LICENSE file for specific language governing | |||
%% rights and limitations of this software. | |||
%% | |||
%% If you have any questions regarding licensing, please contact us at | |||
%% info@rabbitmq.com. | |||
-module(lg_socket_client). | |||
-behavior(gen_statem). | |||
-export([start_link/2]). | |||
-export([stop/1]). | |||
%% gen_statem. | |||
-export([callback_mode/0]). | |||
-export([init/1]). | |||
-export([connect/3]). | |||
-export([open_file/3]). | |||
-export([process_events/3]). | |||
-export([close_file/3]). | |||
-export([code_change/4]). | |||
-export([terminate/3]). | |||
-record(state, { | |||
port :: inet:port_number(), | |||
base_filename :: file:filename_all(), | |||
nth = 0 :: non_neg_integer(), | |||
socket :: inet:socket() | undefined, | |||
io_device :: file:io_device() | undefined, | |||
events_per_frame = 100000 :: pos_integer(), | |||
events_this_frame = 0 :: non_neg_integer(), | |||
buffer = <<>> :: binary() | |||
}). | |||
start_link(Port, BaseFilename) -> | |||
gen_statem:start_link(?MODULE, [Port, BaseFilename], []). | |||
stop(Pid) -> | |||
gen_statem:stop(Pid). | |||
callback_mode() -> | |||
state_functions. | |||
init([Port, BaseFilename]) -> | |||
%% Store all messages off the heap to avoid unnecessary GC. | |||
process_flag(message_queue_data, off_heap), | |||
%% We need to trap exit signals in order to shutdown properly. | |||
process_flag(trap_exit, true), | |||
{ok, connect, #state{port=Port, base_filename=BaseFilename}, | |||
{next_event, internal, run}}. | |||
connect(internal, _, State) -> | |||
do_connect(State); | |||
connect({timeout, retry}, retry, State) -> | |||
do_connect(State); | |||
connect(_, _, State) -> | |||
{keep_state, State}. | |||
do_connect(State=#state{port=Port}) -> | |||
case gen_tcp:connect("localhost", Port, [binary, {packet, 2}, {active, true}]) of | |||
{ok, Socket} -> | |||
{next_state, open_file, State#state{socket=Socket}, | |||
{next_event, internal, run}}; | |||
{error, _} -> | |||
{keep_state, State, [{{timeout, retry}, 1000, retry}]} | |||
end. | |||
open_file(internal, _, State=#state{base_filename=Filename0, nth=Nth}) -> | |||
Filename = filename:flatten([Filename0, ".", integer_to_list(Nth)]), | |||
{ok, IoDevice} = file:open(Filename, [write, raw]), | |||
{next_state, process_events, State#state{nth=Nth + 1, io_device=IoDevice}}. | |||
process_events(info, {tcp, Socket, Bin}, State=#state{socket=Socket, io_device=IoDevice, | |||
events_per_frame=MaxEvents, events_this_frame=NumEvents0, buffer=Buffer0}) -> | |||
BinSize = byte_size(Bin), | |||
Buffer = <<Buffer0/binary, BinSize:16, Bin/binary>>, | |||
NumEvents = NumEvents0 + 1, | |||
if | |||
MaxEvents =:= NumEvents -> | |||
ok = file:write(IoDevice, lz4f:compress_frame(Buffer)), | |||
{keep_state, State#state{events_this_frame=0, buffer= <<>>}}; | |||
true -> | |||
{keep_state, State#state{events_this_frame=NumEvents, buffer=Buffer}} | |||
end; | |||
process_events(info, {tcp_closed, Socket}, State=#state{socket=Socket}) -> | |||
{next_state, close_file, State#state{socket=undefined}, | |||
{next_event, internal, run}}; | |||
process_events(info, {tcp_error, Socket, _}, State=#state{socket=Socket}) -> | |||
_ = gen_tcp:close(Socket), | |||
{next_state, close_file, State#state{socket=undefined}, | |||
{next_event, internal, run}}. | |||
close_file(internal, _, State) -> | |||
do_close_file(State), | |||
{next_state, connect, State#state{io_device=undefined}, | |||
{next_event, internal, run}}. | |||
do_close_file(#state{io_device=IoDevice, buffer=Buffer}) -> | |||
_ = file:write(IoDevice, lz4f:compress_frame(Buffer)), | |||
_ = file:close(IoDevice), | |||
ok. | |||
code_change(_OldVsn, OldState, OldData, _Extra) -> | |||
{callback_mode(), OldState, OldData}. | |||
terminate(_, _, #state{io_device=undefined}) -> | |||
ok; | |||
terminate(_, _, State) -> | |||
do_close_file(State), | |||
ok. |
@ -0,0 +1,148 @@ | |||
%% Copyright (c) 2017-Present Pivotal Software, Inc. All rights reserved. | |||
%% | |||
%% This package, Looking Glass, is double-licensed under the Mozilla | |||
%% Public License 1.1 ("MPL") and the Apache License version 2 | |||
%% ("ASL"). For the MPL, please see LICENSE-MPL-RabbitMQ. For the ASL, | |||
%% please see LICENSE-APACHE2. | |||
%% | |||
%% This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY KIND, | |||
%% either express or implied. See the LICENSE file for specific language governing | |||
%% rights and limitations of this software. | |||
%% | |||
%% If you have any questions regarding licensing, please contact us at | |||
%% info@rabbitmq.com. | |||
-module(lg_socket_tracer). | |||
-export([start_link/2]). | |||
-export([init/2]). | |||
-export([system_continue/3]). | |||
-export([system_terminate/4]). | |||
-export([system_code_change/4]). | |||
-record(state, { | |||
parent :: pid(), | |||
lsocket :: inet:socket(), | |||
timeout_ref :: reference() | undefined | |||
}). | |||
start_link(Nth, BasePort) -> | |||
Pid = proc_lib:spawn_link(?MODULE, init, [self(), BasePort + Nth - 1]), | |||
{ok, Pid}. | |||
init(Parent, Port) -> | |||
%% Store all messages off the heap to avoid unnecessary GC. | |||
process_flag(message_queue_data, off_heap), | |||
%% We need to trap exit signals in order to shutdown properly. | |||
process_flag(trap_exit, true), | |||
%% Open the listening socket. | |||
{ok, LSocket} = gen_tcp:listen(Port, [ | |||
binary, {reuseaddr, true}, {nodelay, true}, | |||
%% We encode all events to binary inside a 2-byte length frame. | |||
{packet, 2}, | |||
%% We expect the client to send pings every second or so and | |||
%% nothing else, so using active mode is faster and still safe. | |||
{active, true}, | |||
%% We only expect one connection at a time. We don't need | |||
%% a backlog except for the cases where the connection is | |||
%% lost and will reconnect immediately before we get a | |||
%% chance to accept again. | |||
{backlog, 1} | |||
%% We are using non-blocking TCP send. We therefore do not | |||
%% need to configure send timeout options. | |||
]), | |||
%% We reject all messages until we get a connection. | |||
accept(#state{parent=Parent, lsocket=LSocket}). | |||
accept(State=#state{lsocket=LSocket}) -> | |||
{ok, AcceptRef} = prim_inet:async_accept(LSocket, -1), | |||
accept_loop(State, AcceptRef). | |||
accept_loop(State=#state{parent=Parent, lsocket=LSocket}, AcceptRef) -> | |||
receive | |||
{'EXIT', Parent, Reason} -> | |||
exit(Reason); | |||
{system, From, Request} -> | |||
sys:handle_system_msg(Request, From, Parent, ?MODULE, [], | |||
{accept_loop, State, AcceptRef}); | |||
{inet_async, LSocket, AcceptRef, {ok, CSocket}} -> | |||
trace_loop(set_timeout(State), CSocket); | |||
{inet_async, LSocket, AcceptRef, Error} -> | |||
exit({accept_error, Error}); | |||
%% We discard all trace events when no client is connected. | |||
%% We may also end up discarding old timeouts or TCP messages. | |||
_ -> | |||
accept_loop(State, AcceptRef) | |||
end. | |||
trace_loop(State=#state{parent=Parent, timeout_ref=TRef}, CSocket) -> | |||
receive | |||
{'EXIT', Parent, Reason} -> | |||
exit(Reason); | |||
{system, From, Request} -> | |||
sys:handle_system_msg(Request, From, Parent, ?MODULE, [], | |||
{trace_loop, State, CSocket}); | |||
%% Reset the timeout when we receive data. | |||
{tcp, CSocket, _} -> | |||
trace_loop(reset_timeout(State), CSocket); | |||
{tcp_closed, CSocket} -> | |||
close(State, CSocket); | |||
{tcp_error, CSocket, _} -> | |||
close(State, CSocket); | |||
{timeout, TRef, ?MODULE} -> | |||
close(State, CSocket); | |||
%% Discard the non-blocking send reply when successful. | |||
{inet_reply, CSocket, ok} -> | |||
trace_loop(State, CSocket); | |||
%% And close the socket when an error occured. | |||
{inet_reply, CSocket, _} -> | |||
close(State, CSocket); | |||
%% Discard TCP messages from closed sockets. | |||
{tcp, _, _} -> | |||
trace_loop(State, CSocket); | |||
{tcp_closed, _} -> | |||
trace_loop(State, CSocket); | |||
{tcp_error, _, _} -> | |||
trace_loop(State, CSocket); | |||
%% Discard any previous timeout. | |||
{timeout, _, ?MODULE} -> | |||
trace_loop(State, CSocket); | |||
Msg -> | |||
Bin = term_to_binary(Msg), | |||
_ = byte_size(Bin), | |||
case erlang:port_command(CSocket, <<Bin/binary>>, [nosuspend]) of | |||
true -> | |||
trace_loop(State, CSocket); | |||
%% The send buffer is full. | |||
false -> | |||
close(State, CSocket) | |||
end | |||
end. | |||
close(State, CSocket) -> | |||
_ = gen_tcp:close(CSocket), | |||
accept(cancel_timeout(State)). | |||
system_continue(_, _, {accept_loop, State, AcceptRef}) -> | |||
accept_loop(State, AcceptRef); | |||
system_continue(_, _, {trace_loop, State, CSocket}) -> | |||
trace_loop(State, CSocket). | |||
-spec system_terminate(any(), _, _, _) -> no_return(). | |||
system_terminate(Reason, _, _, _) -> | |||
exit(Reason). | |||
system_code_change(Misc, _, _, _) -> | |||
{ok, Misc}. | |||
reset_timeout(State) -> | |||
set_timeout(cancel_timeout(State)). | |||
set_timeout(State) -> | |||
TRef = erlang:start_timer(5000, self(), ?MODULE), | |||
State#state{timeout_ref=TRef}. | |||
cancel_timeout(State=#state{timeout_ref=TRef}) -> | |||
_ = erlang:cancel_timer(TRef, [{async, true}, {info, false}]), | |||
State#state{timeout_ref=undefined}. |
@ -0,0 +1,126 @@ | |||
%% Copyright (c) 2017-Present Pivotal Software, Inc. All rights reserved. | |||
%% | |||
%% This package, Looking Glass, is double-licensed under the Mozilla | |||
%% Public License 1.1 ("MPL") and the Apache License version 2 | |||
%% ("ASL"). For the MPL, please see LICENSE-MPL-RabbitMQ. For the ASL, | |||
%% please see LICENSE-APACHE2. | |||
%% | |||
%% This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY KIND, | |||
%% either express or implied. See the LICENSE file for specific language governing | |||
%% rights and limitations of this software. | |||
%% | |||
%% If you have any questions regarding licensing, please contact us at | |||
%% info@rabbitmq.com. | |||
%% Going for hardcoded values for now. We can't spend time | |||
%% looking up inside a record or map for this. | |||
-module(lg_term). | |||
-export([truncate/1]). | |||
-export([truncate/2]). | |||
-define(MAX_DEPTH, 5). | |||
-define(MAX_BINARY_SIZE, 128). | |||
-define(MAX_BITSTRING_SIZE, ?MAX_BINARY_SIZE * 8). | |||
-define(MAX_DATA_STRUCTURES, 5). | |||
-define(MAX_LIST_LENGTH, 32). | |||
-define(MAX_MAP_SIZE, 32). | |||
-define(MAX_TUPLE_SIZE, 32). | |||
truncate(Term) -> | |||
truncate(Term, 1). | |||
truncate(_, Depth) when Depth > ?MAX_DEPTH -> | |||
'$truncated'; | |||
truncate(Term, _) when bit_size(Term) > ?MAX_BITSTRING_SIZE -> | |||
<<Truncated:?MAX_BINARY_SIZE/binary, _/bits>> = Term, | |||
<<Truncated/binary, "$truncated">>; | |||
truncate(Term, Depth) when is_list(Term), Depth =:= ?MAX_DEPTH -> | |||
['$truncated']; | |||
truncate(Term, Depth) when is_list(Term) -> | |||
truncate_list(Term, Depth, 0, ?MAX_LIST_LENGTH, 0); | |||
truncate(Term, Depth) when is_map(Term), Depth =:= ?MAX_DEPTH -> | |||
#{'$truncated' => '$truncated'}; | |||
truncate(Term, Depth) when is_map(Term) -> | |||
maps:from_list(truncate_map(maps_to_list(Term, ?MAX_MAP_SIZE), Depth, 0)); | |||
truncate(Term, Depth) when is_tuple(Term), Depth =:= ?MAX_DEPTH -> | |||
{'$truncated'}; | |||
truncate(Term, Depth) when is_tuple(Term) -> | |||
list_to_tuple(truncate_list(tuple_to_list(Term), Depth, 0, ?MAX_TUPLE_SIZE, 0)); | |||
truncate(Term, _) -> | |||
Term. | |||
truncate_list([], _, _, _, _) -> | |||
[]; | |||
truncate_list(_, _, Len, MaxLen, _) when Len > MaxLen -> | |||
['$truncated']; | |||
truncate_list(_, _, _, _, NumStructs) when NumStructs > ?MAX_DATA_STRUCTURES -> | |||
['$truncated']; | |||
truncate_list([Term|Tail], Depth, Len, MaxLen, NumStructs) -> | |||
[truncate(Term, Depth + 1) | |||
%% if List was a cons, Tail can be anything | |||
|truncate_list(Tail, Depth, Len + 1, MaxLen, NumStructs + is_struct(Term))]; | |||
truncate_list(Term, Depth, _, _, _) -> %% if List was a cons | |||
truncate(Term, Depth + 1). | |||
truncate_map([], _, _) -> | |||
[]; | |||
truncate_map(_, _, NumStructs) when NumStructs > ?MAX_DATA_STRUCTURES -> | |||
[{'$truncated', '$truncated'}]; | |||
truncate_map([{Key, Value}|Tail], Depth, NumStructs) -> | |||
AddStruct = is_struct(Key) + is_struct(Value), | |||
[{truncate(Key, Depth + 1), truncate(Value, Depth + 1)} | |||
|truncate_map(Tail, Depth, NumStructs + AddStruct)]. | |||
is_struct(Term) -> | |||
if | |||
is_list(Term) -> 1; | |||
is_map(Term) -> 1; | |||
is_tuple(Term) -> 1; | |||
true -> 0 | |||
end. | |||
%% Map iterators were introduced in Erlang/OTP 21. They replace | |||
%% the undocumented function erts_internal:maps_to_list/2. | |||
-ifdef(OTP_RELEASE). | |||
maps_to_list(Map, MaxSize) -> | |||
I = maps:iterator(Map), | |||
maps_to_list(maps:next(I), MaxSize, []). | |||
%% Returns elements in arbitrary order. We reverse when we truncate | |||
%% so that the truncated elements come at the end to avoid having | |||
%% two truncated elements in the final output. | |||
maps_to_list(none, _, Acc) -> | |||
Acc; | |||
maps_to_list(_, 0, Acc) -> | |||
lists:reverse([{'$truncated', '$truncated'}|Acc]); | |||
maps_to_list({K, V, I}, N, Acc) -> | |||
maps_to_list(maps:next(I), N - 1, [{K, V}|Acc]). | |||
-else. | |||
maps_to_list(Map, MaxSize) -> | |||
erts_internal:maps_to_list(Map, MaxSize). | |||
-endif. | |||
-ifdef(TEST). | |||
maps_to_list_test() -> | |||
[] = maps_to_list(#{}, 10), | |||
[{'$truncated', '$truncated'}] = maps_to_list(#{a => b}, 0), | |||
[{a, b}] = maps_to_list(#{a => b}, 10), | |||
[{a, b}, {c, d}, {e, f}] = lists:sort(maps_to_list( | |||
#{a => b, c => d, e => f}, 3)), | |||
[{'$truncated', '$truncated'}, {a, b}, {c, d}, {e, f}] = lists:sort(maps_to_list( | |||
#{a => b, c => d, e => f, g => h}, 3)), | |||
[{'$truncated', '$truncated'}, {a, b}, {c, d}, {e, f}] = lists:sort(maps_to_list( | |||
#{a => b, c => d, e => f, g => h, i => j}, 3)), | |||
%% Confirm that truncated values are at the end. | |||
[_, _, _, {'$truncated', '$truncated'}] = maps_to_list( | |||
#{a => b, c => d, e => f, g => h, i => j}, 3), | |||
ok. | |||
-endif. |
@ -0,0 +1,50 @@ | |||
%% Copyright (c) 2017-Present Pivotal Software, Inc. All rights reserved. | |||
%% | |||
%% This package, Looking Glass, is double-licensed under the Mozilla | |||
%% Public License 1.1 ("MPL") and the Apache License version 2 | |||
%% ("ASL"). For the MPL, please see LICENSE-MPL-RabbitMQ. For the ASL, | |||
%% please see LICENSE-APACHE2. | |||
%% | |||
%% This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY KIND, | |||
%% either express or implied. See the LICENSE file for specific language governing | |||
%% rights and limitations of this software. | |||
%% | |||
%% If you have any questions regarding licensing, please contact us at | |||
%% info@rabbitmq.com. | |||
-module(lg_tracer). | |||
%-behavior(erl_tracer). | |||
-export([enabled/3]). | |||
-export([enabled_call/3]). | |||
-export([enabled_procs/3]). | |||
-export([enabled_running_procs/3]). | |||
-export([enabled_send/3]). | |||
-export([trace/5]). | |||
-on_load(on_load/0). | |||
on_load() -> | |||
case code:priv_dir(looking_glass) of | |||
{error, _} -> | |||
{error, {load_failed, "Could not determine the looking_glass priv/ directory."}}; | |||
Path -> | |||
erlang:load_nif(filename:join(Path, atom_to_list(?MODULE)), 0) | |||
end. | |||
enabled(_, _, _) -> | |||
erlang:nif_error({not_loaded, ?MODULE}). | |||
enabled_call(_, _, _) -> | |||
erlang:nif_error({not_loaded, ?MODULE}). | |||
enabled_procs(_, _, _) -> | |||
erlang:nif_error({not_loaded, ?MODULE}). | |||
enabled_running_procs(_, _, _) -> | |||
erlang:nif_error({not_loaded, ?MODULE}). | |||
enabled_send(_, _, _) -> | |||
erlang:nif_error({not_loaded, ?MODULE}). | |||
trace(_, _, _, _, _) -> | |||
erlang:nif_error({not_loaded, ?MODULE}). |
@ -0,0 +1,34 @@ | |||
%% Copyright (c) 2017-Present Pivotal Software, Inc. All rights reserved. | |||
%% | |||
%% This package, Looking Glass, is double-licensed under the Mozilla | |||
%% Public License 1.1 ("MPL") and the Apache License version 2 | |||
%% ("ASL"). For the MPL, please see LICENSE-MPL-RabbitMQ. For the ASL, | |||
%% please see LICENSE-APACHE2. | |||
%% | |||
%% This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY KIND, | |||
%% either express or implied. See the LICENSE file for specific language governing | |||
%% rights and limitations of this software. | |||
%% | |||
%% If you have any questions regarding licensing, please contact us at | |||
%% info@rabbitmq.com. | |||
-module(lg_tracer_pool). | |||
-behaviour(supervisor). | |||
-export([start_link/3]). | |||
-export([init/1]). | |||
-export([tracers/1]). | |||
start_link(NumTracers, TracerMod, Opts) -> | |||
supervisor:start_link(?MODULE, [NumTracers, TracerMod, Opts]). | |||
init([NumTracers, TracerMod, Opts]) -> | |||
Procs = [#{ | |||
id => {tracer, N}, | |||
start => {TracerMod, start_link, [N, Opts]}, | |||
restart => temporary | |||
} || N <- lists:seq(1, NumTracers)], | |||
{ok, {#{strategy => one_for_all}, Procs}}. | |||
tracers(PoolPid) -> | |||
[Pid || {_, Pid, _, _} <- supervisor:which_children(PoolPid)]. |
@ -0,0 +1,25 @@ | |||
%% Copyright (c) 2017-Present Pivotal Software, Inc. All rights reserved. | |||
%% | |||
%% This package, Looking Glass, is double-licensed under the Mozilla | |||
%% Public License 1.1 ("MPL") and the Apache License version 2 | |||
%% ("ASL"). For the MPL, please see LICENSE-MPL-RabbitMQ. For the ASL, | |||
%% please see LICENSE-APACHE2. | |||
%% | |||
%% This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY KIND, | |||
%% either express or implied. See the LICENSE file for specific language governing | |||
%% rights and limitations of this software. | |||
%% | |||
%% If you have any questions regarding licensing, please contact us at | |||
%% info@rabbitmq.com. | |||
-module(looking_glass_app). | |||
-behaviour(application). | |||
-export([start/2]). | |||
-export([stop/1]). | |||
start(_Type, _Args) -> | |||
looking_glass_sup:start_link(). | |||
stop(_State) -> | |||
ok. |
@ -0,0 +1,29 @@ | |||
%% Copyright (c) 2017-Present Pivotal Software, Inc. All rights reserved. | |||
%% | |||
%% This package, Looking Glass, is double-licensed under the Mozilla | |||
%% Public License 1.1 ("MPL") and the Apache License version 2 | |||
%% ("ASL"). For the MPL, please see LICENSE-MPL-RabbitMQ. For the ASL, | |||
%% please see LICENSE-APACHE2. | |||
%% | |||
%% This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY KIND, | |||
%% either express or implied. See the LICENSE file for specific language governing | |||
%% rights and limitations of this software. | |||
%% | |||
%% If you have any questions regarding licensing, please contact us at | |||
%% info@rabbitmq.com. | |||
-module(looking_glass_sup). | |||
-behaviour(supervisor). | |||
-export([start_link/0]). | |||
-export([init/1]). | |||
start_link() -> | |||
supervisor:start_link({local, ?MODULE}, ?MODULE, []). | |||
init([]) -> | |||
Procs = [ | |||
{lg_rabbit_hole, {lg_rabbit_hole, start_link, []}, | |||
permanent, 5000, worker, [lg_rabbit_hole]} | |||
], | |||
{ok, {{one_for_one, 1, 5}, Procs}}. |
@ -0,0 +1,289 @@ | |||
-module(lg_SUITE). | |||
-compile(export_all). | |||
-import(ct_helper, [config/2]). | |||
-import(ct_helper, [doc/1]). | |||
%% ct. | |||
all() -> | |||
[{group, all}]. | |||
%% We cannot run the tests in parallel or they would | |||
%% interfere with each other. | |||
groups() -> | |||
[{all, [], ct_helper:all(?MODULE)}]. | |||
%% Tests. | |||
app(Config) -> | |||
doc("Trace a specific application."), | |||
lg:trace({app, stdlib}, lg_file_tracer, config(priv_dir, Config) ++ "/app.lz4"), | |||
lists:seq(1,10), | |||
lg:stop(), | |||
do_ensure_decompress(config(priv_dir, Config) ++ "/app.lz4"). | |||
callback(Config) -> | |||
doc("Trace using patterns from a callback function."), | |||
lg:trace({callback, ?MODULE, do_callback}, lg_file_tracer, | |||
config(priv_dir, Config) ++ "/callback.lz4"), | |||
lists:seq(1,10), | |||
lg:stop(), | |||
do_ensure_decompress(config(priv_dir, Config) ++ "/callback.lz4"). | |||
do_callback() -> | |||
[{scope, [self()]}, lists]. | |||
callgrind_running(Config) -> | |||
doc("Save events to files on disk then build callgrind files."), | |||
PrivDir = config(priv_dir, Config), | |||
lg:trace([{scope, [self()]}, ?MODULE, {app, stdlib}], lg_file_tracer, | |||
PrivDir ++ "/callgrind_running.lz4", | |||
#{mode => profile, running => true}), | |||
do_callgrind_running(), | |||
lg:stop(), | |||
lg_callgrind:profile_many( | |||
PrivDir ++ "/callgrind_running.lz4.*", | |||
PrivDir ++ "/callgrind_running.out", | |||
#{running => true}), | |||
%% For debugging purposes, print the contents of the callgrind.out files. | |||
%% Uncomment for easier debugging, otherwise look into the files directly. | |||
% _ = [begin | |||
% {ok, File} = file:read_file(PrivDir ++ "/callgrind_running.out." ++ integer_to_list(N)), | |||
% io:format(user, "# callgrind_running.out.~p~n~s", [N, File]), | |||
% lg_file_reader:foreach(fun(E) -> io:format(user, "~p~n", [E]) end, | |||
% PrivDir ++ "/callgrind_running.lz4." ++ integer_to_list(N)) | |||
% end || N <- lists:seq(1, erlang:system_info(schedulers))], | |||
ok. | |||
do_callgrind_running() -> | |||
timer:sleep(1000), | |||
Ref = make_ref(), | |||
erlang:send_after(1000, self(), {go, Ref}), | |||
lists:seq(1,100), | |||
do_callgrind_running_receive(Ref), | |||
lists:seq(1,100), | |||
ok. | |||
do_callgrind_running_receive(Ref) -> | |||
receive | |||
{go, Ref} -> | |||
ok | |||
end. | |||
callgrind_running_cycle(Config) -> | |||
doc("Save events to files on disk then build callgrind files. " | |||
"Create a recursive cycle using two functions calling each other."), | |||
PrivDir = config(priv_dir, Config), | |||
lg:trace([{scope, [self()]}, ?MODULE, {app, stdlib}], lg_file_tracer, | |||
PrivDir ++ "/callgrind_running_cycle.lz4", | |||
#{mode => profile, running => true}), | |||
do_callgrind_running_cycle(), | |||
lg:stop(), | |||
lg_callgrind:profile_many( | |||
PrivDir ++ "/callgrind_running_cycle.lz4.*", | |||
PrivDir ++ "/callgrind_running_cycle.out", | |||
#{running => true}), | |||
%% For debugging purposes, print the contents of the callgrind.out files. | |||
%% Uncomment for easier debugging, otherwise look into the files directly. | |||
% _ = [begin | |||
% {ok, File} = file:read_file(PrivDir ++ "/callgrind_running_cycle.out." ++ integer_to_list(N)), | |||
% io:format(user, "# callgrind_running_cycle.out.~p~n~s", [N, File]), | |||
% lg_file_reader:foreach(fun(E) -> io:format(user, "~p~n", [E]) end, | |||
% PrivDir ++ "/callgrind_running_cycle.lz4." ++ integer_to_list(N)) | |||
% end || N <- lists:seq(1, erlang:system_info(schedulers))], | |||
ok. | |||
do_callgrind_running_cycle() -> | |||
timer:sleep(1000), | |||
lists:seq(1,100), | |||
do_callgrind_running_cycle1(do_callgrind_running_cycle_timer(20)), | |||
lists:seq(1,100), | |||
ok. | |||
do_callgrind_running_cycle_timer(N) -> | |||
erlang:start_timer(N * 10, self(), N). | |||
do_callgrind_running_cycle1(Ref) -> | |||
receive | |||
{timeout, Ref, 0} -> | |||
ok; | |||
{timeout, Ref, N} when N rem 5 =:= 0 -> | |||
do_callgrind_running_cycle2(do_callgrind_running_cycle_timer(N - 1)); | |||
{timeout, Ref, N} -> | |||
do_callgrind_running_cycle1(do_callgrind_running_cycle_timer(N - 1)) | |||
end. | |||
do_callgrind_running_cycle2(Ref) -> | |||
receive | |||
{timeout, Ref, 0} -> | |||
ok; | |||
{timeout, Ref, N} when N rem 4 =:= 0 -> | |||
do_callgrind_running_cycle1(do_callgrind_running_cycle_timer(N - 1)); | |||
{timeout, Ref, N} -> | |||
do_callgrind_running_cycle2(do_callgrind_running_cycle_timer(N - 1)) | |||
end. | |||
file_tracer(Config) -> | |||
doc("Save events to files on disk."), | |||
lg:trace(lists, lg_file_tracer, config(priv_dir, Config) ++ "/file_tracer.lz4"), | |||
lists:seq(1,10), | |||
lg:stop(), | |||
do_ensure_decompress(config(priv_dir, Config) ++ "/file_tracer.lz4"). | |||
file_tracer_rotation(Config) -> | |||
doc("Save events to files on disk; rotate the files if they get too big."), | |||
Prefix = config(priv_dir, Config) ++ "/file_tracer.lz4", | |||
lg:trace(lists, lg_file_tracer, #{ | |||
filename_prefix => Prefix, | |||
max_size => 100, %% Intentionally low. | |||
events_per_frame => 10 %% Needed to trigger the rotation, default is too high. | |||
}), | |||
lists:seq(1,1000), | |||
lg:stop(), | |||
%% We should have one or more rotated files. | |||
Result = [begin | |||
Filename = Prefix ++ "." ++ integer_to_list(N) ++ ".bak", | |||
filelib:is_file(Filename) | |||
end || N <- lists:seq(1, erlang:system_info(schedulers))], | |||
true = lists:member(true, lists:usort(Result)), | |||
ok. | |||
mod(Config) -> | |||
doc("Trace a specific module."), | |||
lg:trace(lists, lg_file_tracer, config(priv_dir, Config) ++ "/mod.lz4"), | |||
lists:seq(1,10), | |||
lg:stop(), | |||
do_ensure_decompress(config(priv_dir, Config) ++ "/mod.lz4"). | |||
profile_mode(Config) -> | |||
doc("Trace a specific module in profile mode."), | |||
lg:trace(lists, lg_file_tracer, config(priv_dir, Config) ++ "/profile_mode.lz4", | |||
#{mode => profile}), | |||
lists:seq(1,10), | |||
lg:stop(), | |||
do_ensure_decompress(config(priv_dir, Config) ++ "/profile_mode.lz4"). | |||
raw_console_tracer(_) -> | |||
doc("Print raw events to the console."), | |||
ct:print("Start tracing to the console."), | |||
%% @todo It seems the order matters when starting. Should it? | |||
lg:trace([{scope, [self()]}, lists]), | |||
lists:seq(1,10), | |||
lg:stop(), | |||
ct:print("Stop tracing to the console."). | |||
running_true(Config) -> | |||
doc("Trace a specific module with running option enabled."), | |||
lg:trace(lists, lg_file_tracer, config(priv_dir, Config) ++ "/running_true.lz4", | |||
#{running => true}), | |||
lists:seq(1,10), | |||
lg:stop(), | |||
do_ensure_decompress(config(priv_dir, Config) ++ "/running_true.lz4"). | |||
send_true(Config) -> | |||
doc("Trace a specific module with send option enabled."), | |||
lg:trace(lists, lg_file_tracer, config(priv_dir, Config) ++ "/send_true.lz4", | |||
#{send => true}), | |||
Self = self(), | |||
%% Send a message to and from an existing process. | |||
Pid = spawn(fun() -> | |||
receive {msg_from, Self} -> | |||
Self ! {msg_from, self()} | |||
end | |||
end), | |||
Pid ! {msg_from, Self}, | |||
receive {msg_from, Pid} -> ok end, | |||
%% Also send a message to a non existing process. | |||
DeadPid = spawn(fun() -> ok end), | |||
receive after 100 -> ok end, | |||
DeadPid ! {msg_from, Self}, | |||
lg:stop(), | |||
do_ensure_decompress(config(priv_dir, Config) ++ "/send_true.lz4"). | |||
socket_tracer(_) -> | |||
doc("Send events to a socket."), | |||
Port = 61234, | |||
lg:trace(lists, lg_socket_tracer, Port, #{pool_size => 1}), | |||
{ok, Socket} = gen_tcp:connect("localhost", Port, | |||
[binary, {packet, 2}, {active, true}]), | |||
lists:seq(1,10), | |||
lg:stop(), | |||
do_socket_tracer_recv(Socket). | |||
socket_tracer_client(Config) -> | |||
doc("Send events to a socket client."), | |||
Port = 61234, | |||
lg:trace(lists, lg_socket_tracer, Port, #{pool_size => 1}), | |||
BaseFilename = config(priv_dir, Config) ++ "/socket_tracer_client.lz4", | |||
{ok, Pid} = lg_socket_client:start_link(Port, BaseFilename), | |||
timer:sleep(1000), | |||
lists:seq(1,10), | |||
lg:stop(), | |||
lg_socket_client:stop(Pid), | |||
{ok, File} = file:read_file(BaseFilename ++ ".0"), | |||
_ = lz4f:decompress(File), | |||
true = filelib:file_size(BaseFilename ++ ".0") > 0, | |||
ok. | |||
socket_tracer_many(_) -> | |||
doc("Send events to many sockets."), | |||
Port = 61234, | |||
lg:trace(lists, lg_socket_tracer, Port, #{pool_size => 5}), | |||
{ok, _} = gen_tcp:connect("localhost", Port, []), | |||
{ok, _} = gen_tcp:connect("localhost", Port + 1, []), | |||
{ok, _} = gen_tcp:connect("localhost", Port + 2, []), | |||
{ok, _} = gen_tcp:connect("localhost", Port + 3, []), | |||
{ok, _} = gen_tcp:connect("localhost", Port + 4, []), | |||
{error, _} = gen_tcp:connect("localhost", Port + 5, []), | |||
lg:stop(). | |||
socket_tracer_reconnect(_) -> | |||
doc("Confirm we can reconnect to the tracer."), | |||
Port = 61234, | |||
lg:trace(lists, lg_socket_tracer, Port, #{pool_size => 1}), | |||
{ok, Socket0} = gen_tcp:connect("localhost", Port, | |||
[binary, {packet, 2}, {active, true}]), | |||
ok = gen_tcp:close(Socket0), | |||
{ok, Socket} = gen_tcp:connect("localhost", Port, | |||
[binary, {packet, 2}, {active, true}]), | |||
lists:seq(1,10), | |||
lg:stop(), | |||
do_socket_tracer_recv(Socket). | |||
do_socket_tracer_recv(Socket) -> | |||
receive | |||
{tcp, Socket, Data} -> | |||
Term = binary_to_term(Data), | |||
true = is_tuple(Term), | |||
do_socket_tracer_recv(Socket); | |||
{tcp_closed, Socket} -> | |||
ok | |||
after 1000 -> | |||
error(timeout) | |||
end. | |||
stop_while_trace_is_running(Config) -> | |||
doc("Stop tracing while events are still coming in."), | |||
Self = self(), | |||
Pid = spawn_link(fun() -> Self ! {self(), continue}, lists:seq(1,10000000) end), | |||
lg:trace([{scope, [Pid]}, lists], lg_file_tracer, | |||
config(priv_dir, Config) ++ "/stop_while_trace_is_running.lz4"), | |||
receive {Pid, continue} -> ok after 100 -> error(timeout) end, | |||
lg:stop(), | |||
do_ensure_decompress(config(priv_dir, Config) ++ "/stop_while_trace_is_running.lz4"). | |||
%% Internal. | |||
do_ensure_decompress(Prefix) -> | |||
%% Ensure the files can be decompressed. | |||
Sizes = [begin | |||
Filename = Prefix ++ "." ++ integer_to_list(N), | |||
{ok, File} = file:read_file(Filename), | |||
_ = lz4f:decompress(File), | |||
filelib:file_size(Filename) | |||
end || N <- lists:seq(1, erlang:system_info(schedulers))], | |||
%% We also need to make sure there is actual data in the files, | |||
%% as lz4f:decompress will succeed when provided with no data. | |||
true = 0 < lists:sum(Sizes), | |||
ok. |