Commit 27d0aaf2 authored by Philip Carns's avatar Philip Carns
Browse files

Merge branch 'master' into 'master'

Add breadcrumb profiling logic

See merge request !18
parents ea6ff6b0 7fb90671
......@@ -3,6 +3,9 @@ ACLOCAL_AMFLAGS = -I m4
bin_PROGRAMS =
bin_SCRIPTS =
dist_bin_SCRIPTS = scripts/margo-gen-profile
dist_noinst_SCRIPTS = scripts/margo-gen-profile
noinst_PROGRAMS =
noinst_HEADERS =
TESTS =
......@@ -15,7 +18,8 @@ EXTRA_DIST =
BUILT_SOURCES =
include_HEADERS = \
include/margo.h \
include/margo-bulk-pool.h
include/margo-bulk-pool.h \
include/margo-diag.h
TESTS_ENVIRONMENT =
......
# Margo instrumentation
This file documents instrumentation capabilities that are built into the
This file documents instrumentation and profiling capabilities that are built into the
margo library. See the [top level README.md](../README.md) for general
information about margo.
Margo includes two forms of instrumentation. The first measures time spent
Margo includes two levels of instrumentation and profiling. The first (diagnostics) measures time spent
executing key Mercury functions within the communication progress
loop. The second measures time spent invoking remote procedure calls.
loop. The second (breadcrumb profiling) measures time spent invoking remote procedure calls.
## Usage
Both can be enabled at run time by calling the `margo_diag_start()` any
Diagnostics can be enabled in two ways:
* At program startup, using the env variable `MARGO_ENABLE_DIAGNOSTICS`.
* At run time by calling the `margo_diag_start()` any
time after `margo_init()` on the process that you wish to instrument.
Statistics from both can then be emitted at any time prior to
`margo_finalize()` by calling the `margo_diag_dump()` function.
The arguments to `margo_diag_dump()` are as follows:
Statistics from mercury diagnostics can then be emitted at any time prior to
`margo_finalize()` by calling the `margo_diag_dump()` function. Diagnostics
can be stopped by calling the `margo_diag_stop` on the process.
Similarly, profining can by enabled/disabled either by use of the environment
variable `MARGO_ENABLE_PROFILING` or by using the `margo_profile_start`/`margo_profile_stop`
functions. Statistics from profiling can be output by invoking the `margo_profile_dump`
on the process.
The arguments to `margo_diag_dump()` and `margo_profile_dump` are as follows:
* `mid`: the margo instance to retrieve instrumentation from
* `file`: name of the file to write the (text) data to. If the "-" string
is used, then data will be written to `STDOUT`.
* `uniquify`: flag indicating that the file name should be suffixed with
additional characters to make it unique from other diagnostic files emited
additional characters to make it unique from other files emited
on the same node.
## Output format
* Diagnostic files have the *.diag suffix for the file name, and
profile files have the *.csv suffix.
* If the environment variable is used to control diagnostics/profiling,
all the corresponding files have the default "profile" prefix to the name.
Additionally, the `uniqufy` flag is set, causing the generation of one profile
file for every margo process instance.
## Diagnostics Output Format
Example output from `margo_diag_dump()` will look like this for a given
processes:
```
# Margo diagnostics
# Wed Jul 31 11:15:13 2019
# Addr Hash and Address Name: 18446744035473536664, ofi+sockets://10.3.1.23:46282
# Tue Oct 8 20:20:08 2019
# RPC breadcrumbs for RPCs that were registered on this process:
# 0x5f22 data_xfer_read
# 0xa1ef delegator_read
# 0x5f22 data_xfer_read
# 0x9245 my_shutdown_rpc
# <stat> <avg> <min> <max> <count>
# Time consumed by HG_Trigger()
trigger_elapsed 0.000000036 0.000000238 0.000114679 3911094
# Time consumed by HG_Progress() when called with timeout==0
progress_elapsed_zero_timeout 0.000004716 0.000000238 0.016073227 3909480
# Time consumed by HG_Progress() when called with timeout!=0
progress_elapsed_nonzero_timeout 0.051754011 0.000023842 0.100308180 411
# Timeout values passed to HG_Progress()
progress_timeout_value 0.010511802 0.000000000 100.000000000 3909891
# RPC statistics
0x5f22 0xa1ef 0x0000 0x0000 0.001448274 0.001207113 0.007883787 100
# Function Name, Average Time Per Call, Cumulative Time, Highwatermark, Lowwatermark, Call Count
trigger_elapsed,0.000000047,2.650168180,0.000000238,0.010999918,56241640
progress_elapsed_zero_timeout,0.000000755,42.434520245,0.000000477,0.129006147,56173943
progress_elapsed_nonzero_timeout,0.000000000,0.000000000,0.000000000,0.000000000,0
```
Key components of the output are:
* A table of RPC names registered on that processes. Each has a 16 bit
hexadecimal identifier and a string name. There may be duplicates in the
table if the same RPC is registered more than once on the process.
* A set of statistics for Mercury functions used to drive communication and
* The assigned unique network address of the margo instance and its 64-bit hash.
* A set of basic statistics for Mercury functions used to drive communication and
completion project. There are counters and elapsed time measurements for
the `HG_Trigger()` function and the `HG_Progress()` function (when called with
or without a timeout value, as Margo varies its pollin strategy). There
is also a category that records statistics about the actual timeout values
used.
* A set of statistics for each RPC that was _issued_ by the process (in the
"RPC statistics" category at the end. Each RPC will be identified by a
set of up to 4 hexidecmial identifiers. The set of identifiers represents a
stack that shows the heritage of up to 4 chained RPCS that lead to this
* This file is intended to be read by the end-user directly.
## Profiling Output Format
```
90
18446744035473536664,ofi+sockets://10.3.1.23:46282
0xdea7,mobject_server_stat
0x9166,mobject_server_clean
0x8bbe,mobject_read_op
0x45b1,mobject_write_op
0x03cb,sdskv_migrate_database_rpc
0xf8d6,sdskv_migrate_all_keys_rpc
0x70d7,sdskv_migrate_keys_prefixed_rpc
0x49e1,sdskv_migrate_key_range_rpc
0x9ce7,sdskv_migrate_keys_rpc
0x2cb7,sdskv_list_keyvals_rpc
0x3598,sdskv_list_keys_rpc
0xf4dc,sdskv_bulk_get_rpc
0x0afa,sdskv_length_multi_rpc
0x5518,sdskv_length_rpc
0x1e99,sdskv_exists_rpc
0xc2bd,sdskv_erase_multi_rpc
0xcaf8,sdskv_erase_rpc
0x98d0,sdskv_get_multi_rpc
0x6488,sdskv_get_rpc
0x8cc0,sdskv_bulk_put_rpc
0xc083,sdskv_put_multi_rpc
0x9695,sdskv_put_rpc
0x4482,sdskv_list_databases_rpc
0x2154,sdskv_count_databases_rpc
0x89b3,sdskv_open_rpc
0xec2c,remi_migrate_end
0x3be8,bake_probe_rpc
0x098f,bake_persist_rpc
...
...
...
0x3be8 ,0.000013113,15336,18446744035473536664,1,0.000013113,0.000013113,0.000013113,1,18446744073709551615,0,0,18446744073709551615,0,0
0x3be8 ,1;0.000013113,1.000000000, 0;0.000000000,0.000000000, 1;0.000013113,1.000000000, 2;0.000000000,0.000000000, 3;0.000013113,1.000000000, 4
0x098f 0x45b1 ,0.011572483,1169230223,18446744035473536664,0,4.397543430,0.008075237,0.020334244,380,18446744073709551615,286331153,0,18446744073709551615,286331153,0
0x098f 0x45b1 ,0;0.000000000,0.000000000, 0;0.000000000,0.000000000, 1;0.000000000,0.000000000, 2;0.000000000,0.000000000, 3;0.000000000,0.000000000, 4
...
...
```
Key components of the output are:
* First line always contains the number of RPC names registered on that process.
* Second line is the assigned unique network address of the margo instance and its 64-bit hash.
* Next, a table of RPC names registered on that process. Each has a 16 bit
hexadecimal identifier and a string name. There may be duplicates in the
table if the same RPC is registered more than once on the process.
* A set of statistics for each RPC that was issued or received by that margo instance.
Each RPC will be identified by a set of up to 4 hexidecmial identifiers.
The set of identifiers represents a stack that shows the heritage of up to 4 chained RPCS that lead to this
measurement. Each identifier will match a name in the table at the top.
In the above example, only one RPC was issued by this
process: a "data_xfer_read" RPC that was issed as a side effect of a
"delegator_read" RPC.
In the above example, statistics are shown for two RPCs (among others in the profile): the "bake_probe_rpc"
was executed by this server margo process. Additionally, the "bake_persist_rpc" was issued by this server margo process
that was the side of receiving and executing a "mobject_write_op" request from a client.
* RPC calls made from the margo instance in question to different margo server instances, or issued by different margo client instances
to the margo instance in question are distinguished in the profile.
Additionally, the RPC statistic also indicates if it represents a client making a call or a server executing a call.
* Each RPC statistic is associated with 2 consecutive lines in the profile: One containing profiling statistics such as timing information,
and the other representing information to be used in the generation of a sparkline.
* The user must keep in mind that the profiles only represent the RPC statistics. This is not the same as request tracing.
## Implementation
## Generating a Profile and Topology Graph
While the diagnostic files are simple enough to be read and understood by the user,
the profile files, although readable, represent too much information to be processed
manually. Thus, we have developed a "profile generator" that reads the *.csv files
in the current working directory and generates a PDF file summarizing important
performance statistics that can help in detecting load imbalance among margo instances,
relative call-counts and calltimes for various RPC breadcrumbs, and so on.
## Future directions and use cases
In order to the generate the PDF summarizing performance, follow these steps:
* Enable profiling in your margo instances (easiest way is to use the `MARGO_ENABLE_PROFILING`
environment variable).
* Add the $MARGO_INSTALL/bin to your path, and run the MOCHI program.
* After the program executes, verify that the current directory contains the *.csv files.
* Invoke the ```margo-gen-profile``` program in the directory containing the *.csv.
This will generate a ```profile.pdf``` and a ```graph.gv``` file.
* The ```profile.pdf``` contains a list of graphs summarizing various performance statistics.
For example, the following is a graph representing the top-5 breadcrumbs
sorted by cumulative call times on the origin (client) and the target (server): ![](fig/profile.png)
* The ```graph.gv``` file is a ```graphViz``` file that represents a topology graph
of the MOCHI service setup. This is a visual representation of the RPC calls
and location of various margo processes mapped onto the physical system.
If the user has ```graphViz``` installed, a PNG file can be generated using
the command ```dot -Tpng graph.gv -o gg.png```, and the resulting image would
look like: ![](fig/gg.png)
/*
* (C) 2015 The University of Chicago
*
* See COPYRIGHT in top-level directory.
*/
#include <stdio.h> /* defines printf for tests */
#include <time.h> /* defines time_t for timings in the test */
#include <stdint.h> /* defines uint32_t etc */
#include <sys/param.h> /* attempt to define endianness */
#ifdef linux
# include <endian.h> /* attempt to define endianness */
#endif
#ifndef __MARGO_DIAG
#define __MARGO_DIAG
#ifdef __cplusplus
extern "C" {
#endif
#define GET_SELF_ADDR_STR(__mid, __addr_str) do { \
hg_addr_t __self_addr; \
hg_size_t __size; \
__addr_str = NULL; \
if (margo_addr_self(__mid, &__self_addr) != HG_SUCCESS) break; \
if (margo_addr_to_string(__mid, NULL, &__size, __self_addr) != HG_SUCCESS) { \
margo_addr_free(__mid, __self_addr); \
break; \
} \
if ((__addr_str = malloc(__size)) == NULL) { \
margo_addr_free(__mid, __self_addr); \
break; \
} \
if (margo_addr_to_string(__mid, __addr_str, &__size, __self_addr) != HG_SUCCESS) { \
free(__addr_str); \
__addr_str = NULL; \
margo_addr_free(__mid, __self_addr); \
break; \
} \
margo_addr_free(__mid, __self_addr); \
} while(0)
/******************************************************************************************************/
/* used to identify a globally unique breadcrumb */
struct global_breadcrumb_key
{
uint64_t rpc_breadcrumb; /* a.k.a RPC callpath */
uint64_t addr_hash; /* hash of server addr */
uint16_t provider_id; /* provider_id within a server. NOT a globally unique identifier */
};
enum breadcrumb_type
{
origin, target
};
typedef enum breadcrumb_type breadcrumb_type;
struct breadcrumb_stats
{
/* stats for breadcrumb call times */
double min;
double max;
double cumulative;
/* stats for RPC handler pool sizes */
/* Total pool size = Total number of runnable items + items waiting on a lock */
unsigned long abt_pool_total_size_lwm; /* low watermark */
unsigned long abt_pool_total_size_hwm; /* high watermark */
unsigned long abt_pool_total_size_cumulative;
unsigned long abt_pool_size_lwm; /* low watermark */
unsigned long abt_pool_size_hwm; /* high watermark */
unsigned long abt_pool_size_cumulative;
/* count of occurrences of breadcrumb */
unsigned long count;
};
typedef struct breadcrumb_stats breadcrumb_stats;
/* structure to store breadcrumb snapshot, for consumption outside of margo.
reflects the margo-internal structure used to hold diagnostic data */
struct margo_breadcrumb
{
breadcrumb_stats stats;
/* 0 is this is a origin-side breadcrumb, 1 if this is a target-side breadcrumb */
breadcrumb_type type;
struct global_breadcrumb_key key;
struct margo_breadcrumb* next;
};
/* snapshot contains linked list of breadcrumb data */
struct margo_breadcrumb_snapshot
{
struct margo_breadcrumb* ptr;
};
#ifdef __cplusplus
}
#endif
#endif /* __MARGO_DIAG */
......@@ -17,6 +17,8 @@ extern "C" {
#include <mercury_macros.h>
#include <abt.h>
#include "margo-diag.h"
/* determine how much of the Mercury ID space to use for Margo provider IDs */
#define __MARGO_PROVIDER_ID_SIZE (sizeof(hg_id_t)/4)
#define __MARGO_RPC_HASH_SIZE (__MARGO_PROVIDER_ID_SIZE * 3)
......@@ -41,6 +43,8 @@ typedef struct margo_request_struct* margo_request;
#define MARGO_MAX_PROVIDER_ID ((1 << (8*__MARGO_PROVIDER_ID_SIZE))-1)
#define MARGO_PARAM_PROGRESS_TIMEOUT_UB 1
#define MARGO_PARAM_ENABLE_PROFILING 2
#define MARGO_PARAM_ENABLE_DIAGNOSTICS 3
/**
* Initializes margo library.
......@@ -900,6 +904,30 @@ margo_instance_id margo_hg_info_get_instance(const struct hg_info *info);
*/
void margo_diag_start(margo_instance_id mid);
/**
* Enables profile data collection on specified Margo instance
*
* @param [in] mid Margo instance
* @returns void
*/
void margo_profile_start(margo_instance_id mid);
/**
* Disables diagnostic collection on specified Margo instance
*
* @param [in] mid Margo instance
* @returns void
*/
void margo_diag_stop(margo_instance_id mid);
/**
* Disables profile data collection on specified Margo instance
*
* @param [in] mid Margo instance
* @returns void
*/
void margo_profile_stop(margo_instance_id mid);
/**
* Appends diagnostic statistics (enabled via margo_diag_start()) to specified
* output file.
......@@ -912,6 +940,27 @@ void margo_diag_start(margo_instance_id mid);
*/
void margo_diag_dump(margo_instance_id mid, const char* file, int uniquify);
/**
* Appends profile statistics (enabled via margo_profile_start()) to specified
* output file.
*
* @param [in] mid Margo instance
* @param [in] file output file ("-" for stdout)
* @param [in] uniquify flag indicating if file name should have additional
* information added to it to make output from different processes unique
* @returns void
*/
void margo_profile_dump(margo_instance_id mid, const char* file, int uniquify);
/**
* Grabs a snapshot of the current state of diagnostics within the margo instance
*
* @param [in] mid Margo instance
* @param [out] snap Margo diagnostics snapshot
* @returns void
*/
void margo_breadcrumb_snapshot(margo_instance_id mid, struct margo_breadcrumb_snapshot* snap);
/**
* Sets configurable parameters/hints
*
......
This diff is collapsed.
This diff is collapsed.
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment