commit 2831004eb17347a5688f0f70004077690952cdb7 Author: SisMaker <1713699517@qq.com> Date: Wed May 19 00:42:15 2021 +0800 ft: 初始化提交 diff --git a/.gitignore b/.gitignore new file mode 100644 index 0000000..0ad44f1 --- /dev/null +++ b/.gitignore @@ -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 \ No newline at end of file diff --git a/LICENSE b/LICENSE new file mode 100644 index 0000000..401d523 --- /dev/null +++ b/LICENSE @@ -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. diff --git a/README.md b/README.md new file mode 100644 index 0000000..72112ae --- /dev/null +++ b/README.md @@ -0,0 +1,9 @@ +eTpf +===== + +An OTP application + +Build +----- + + $ rebar3 compile diff --git a/c_src/tracer/lg_tracer.c b/c_src/tracer/lg_tracer.c new file mode 100644 index 0000000..be4f034 --- /dev/null +++ b/c_src/tracer/lg_tracer.c @@ -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) diff --git a/c_src/tracer/nif_helpers.c b/c_src/tracer/nif_helpers.c new file mode 100644 index 0000000..f29d76d --- /dev/null +++ b/c_src/tracer/nif_helpers.c @@ -0,0 +1,195 @@ +// Copyright (c) 2014-2015, Loïc Hoguin +// +// 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 +#include + +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); +} diff --git a/c_src/tracer/nif_helpers.h b/c_src/tracer/nif_helpers.h new file mode 100644 index 0000000..2eefec6 --- /dev/null +++ b/c_src/tracer/nif_helpers.h @@ -0,0 +1,139 @@ +// Copyright (c) 2014-2015, Loïc Hoguin +// +// 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 diff --git a/rebar.config b/rebar.config new file mode 100644 index 0000000..a2dfdfe --- /dev/null +++ b/rebar.config @@ -0,0 +1,7 @@ +{erl_opts, [debug_info]}. +{deps, []}. + +{shell, [ + % {config, "config/sys.config"}, + {apps, [eTpf]} +]}. diff --git a/src/doc/book.asciidoc b/src/doc/book.asciidoc new file mode 100644 index 0000000..36ce0ce --- /dev/null +++ b/src/doc/book.asciidoc @@ -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] diff --git a/src/doc/callgrind.asciidoc b/src/doc/callgrind.asciidoc new file mode 100644 index 0000000..c34444a --- /dev/null +++ b/src/doc/callgrind.asciidoc @@ -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. diff --git a/src/doc/flame.asciidoc b/src/doc/flame.asciidoc new file mode 100644 index 0000000..7bb976d --- /dev/null +++ b/src/doc/flame.asciidoc @@ -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. diff --git a/src/doc/introduction.asciidoc b/src/doc/introduction.asciidoc new file mode 100644 index 0000000..b977ab3 --- /dev/null +++ b/src/doc/introduction.asciidoc @@ -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]. diff --git a/src/doc/messages.asciidoc b/src/doc/messages.asciidoc new file mode 100644 index 0000000..34db683 --- /dev/null +++ b/src/doc/messages.asciidoc @@ -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> '' +30351 <7782.382.0> pause + <7782.391.0> {'$gen_cast',{deliver,{...},...}} +29894 <7782.375.0> '' + <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. diff --git a/src/doc/seq.png b/src/doc/seq.png new file mode 100644 index 0000000..3661c2f Binary files /dev/null and b/src/doc/seq.png differ diff --git a/src/doc/tracing.asciidoc b/src/doc/tracing.asciidoc new file mode 100644 index 0000000..c22c9f2 --- /dev/null +++ b/src/doc/tracing.asciidoc @@ -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 +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. diff --git a/src/eTpf.app.src b/src/eTpf.app.src new file mode 100644 index 0000000..77172f8 --- /dev/null +++ b/src/eTpf.app.src @@ -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, []} + ]}. diff --git a/src/eTpf_app.erl b/src/eTpf_app.erl new file mode 100644 index 0000000..84fa3c9 --- /dev/null +++ b/src/eTpf_app.erl @@ -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 diff --git a/src/eTpf_sup.erl b/src/eTpf_sup.erl new file mode 100644 index 0000000..81e2b4e --- /dev/null +++ b/src/eTpf_sup.erl @@ -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 diff --git a/src/lg.erl b/src/lg.erl new file mode 100644 index 0000000..4966a95 --- /dev/null +++ b/src/lg.erl @@ -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). diff --git a/src/lg_callgrind.erl b/src/lg_callgrind.erl new file mode 100644 index 0000000..24ec4b6 --- /dev/null +++ b/src/lg_callgrind.erl @@ -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(<>, 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}. diff --git a/src/lg_file_reader.erl b/src/lg_file_reader.erl new file mode 100644 index 0000000..d6bca3c --- /dev/null +++ b/src/lg_file_reader.erl @@ -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 + <> -> + 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= <>, + 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). diff --git a/src/lg_file_tracer.erl b/src/lg_file_tracer.erl new file mode 100644 index 0000000..b8e8da7 --- /dev/null +++ b/src/lg_file_tracer.erl @@ -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 = <>, + 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). diff --git a/src/lg_flame.erl b/src/lg_flame.erl new file mode 100644 index 0000000..b86e75c --- /dev/null +++ b/src/lg_flame.erl @@ -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). diff --git a/src/lg_messages.erl b/src/lg_messages.erl new file mode 100644 index 0000000..a35874d --- /dev/null +++ b/src/lg_messages.erl @@ -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, ''), ""} + 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}}. diff --git a/src/lg_messages_seqdiag.erl b/src/lg_messages_seqdiag.erl new file mode 100644 index 0000000..3033a66 --- /dev/null +++ b/src/lg_messages_seqdiag.erl @@ -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. diff --git a/src/lg_rabbit_hole.erl b/src/lg_rabbit_hole.erl new file mode 100644 index 0000000..688e0ce --- /dev/null +++ b/src/lg_rabbit_hole.erl @@ -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}. diff --git a/src/lg_raw_console_tracer.erl b/src/lg_raw_console_tracer.erl new file mode 100644 index 0000000..a6f02f0 --- /dev/null +++ b/src/lg_raw_console_tracer.erl @@ -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}. diff --git a/src/lg_socket_client.erl b/src/lg_socket_client.erl new file mode 100644 index 0000000..21aa5ae --- /dev/null +++ b/src/lg_socket_client.erl @@ -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 = <>, + 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. diff --git a/src/lg_socket_tracer.erl b/src/lg_socket_tracer.erl new file mode 100644 index 0000000..0238f2d --- /dev/null +++ b/src/lg_socket_tracer.erl @@ -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, <>, [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}. diff --git a/src/lg_term.erl b/src/lg_term.erl new file mode 100644 index 0000000..0093a59 --- /dev/null +++ b/src/lg_term.erl @@ -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 -> + <> = Term, + <>; +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. diff --git a/src/lg_tracer.erl b/src/lg_tracer.erl new file mode 100644 index 0000000..1eba511 --- /dev/null +++ b/src/lg_tracer.erl @@ -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}). diff --git a/src/lg_tracer_pool.erl b/src/lg_tracer_pool.erl new file mode 100644 index 0000000..f9fd30d --- /dev/null +++ b/src/lg_tracer_pool.erl @@ -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)]. diff --git a/src/looking_glass_app.erl b/src/looking_glass_app.erl new file mode 100644 index 0000000..c8f3b53 --- /dev/null +++ b/src/looking_glass_app.erl @@ -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. diff --git a/src/looking_glass_sup.erl b/src/looking_glass_sup.erl new file mode 100644 index 0000000..613ea87 --- /dev/null +++ b/src/looking_glass_sup.erl @@ -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}}. diff --git a/test/lg_SUITE.erl b/test/lg_SUITE.erl new file mode 100644 index 0000000..c69fa24 --- /dev/null +++ b/test/lg_SUITE.erl @@ -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.