[PATCH 1/2 RFC] Add time stamp collection to operf and opreport
"Carl E. Love" <[email protected]>
| Newsgroups | gmane.linux.oprofile |
|---|---|
| Message-ID | <1443803979.6530.56.camel@oc3328482554> |
Add time stamp collection to operf, report timestamps in XML output This patch adds a command line option to operf to collect time stamp data for each sample. The time stamps are printed to the various oprofile data files. The opreport command also has a command line option added. This option will print the time stamp data in the XML output file for each sample. If the -d option is used the time stamps will also be printed for each instruct in the detailed XML output file. Signed-off-by: Carl Love <[email protected]> --- doc/operf.1.in | 8 +- doc/opreport.1.in | 7 +- doc/opreport.xsd | 2 + libabi/opimport.cpp | 2 +- libabi/tests/abi_test.cpp | 2 +- libdb/db_insert.c | 30 +++- libdb/db_manage.c | 296 +++++++++++++++++++++++++++++++++++++- libdb/odb.h | 29 +++- libop/op_config.h | 2 + libop/op_xml_out.c | 1 + libop/op_xml_out.h | 1 + libperf_events/operf_counter.cpp | 18 ++- libperf_events/operf_counter.h | 7 +- libperf_events/operf_sfile.cpp | 8 +- libperf_events/operf_sfile.h | 1 + libperf_events/operf_utils.cpp | 9 ++ libpp/callgraph_container.cpp | 3 +- libpp/format_output.cpp | 81 ++++++++++- libpp/format_output.h | 5 + libpp/op_header.h | 2 + libpp/profile.cpp | 56 ++++++-- libpp/profile.h | 32 +++-- libpp/profile_container.cpp | 33 ++++- libpp/profile_container.h | 8 +- libpp/symbol.cpp | 7 + libpp/symbol.h | 8 + libpp/symbol_container.cpp | 1 + libpp/xml_utils.cpp | 45 ++++++- libpp/xml_utils.h | 3 + pe_profiling/operf.cpp | 10 +- pp/opgprof.cpp | 8 +- pp/opreport.cpp | 9 +- pp/opreport_options.cpp | 14 ++ pp/opreport_options.h | 1 + 34 files changed, 682 insertions(+), 67 deletions(-) diff --git a/doc/operf.1.in b/doc/operf.1.in index efaceb9..a9129de 100644 --- a/doc/operf.1.in +++ b/doc/operf.1.in @@ -10,7 +10,7 @@ operf \- Performance profiler tool for Linux [ .I options ] -[ --system-wide | --pid <pid> | [ command [ args ] ] ] +[ --system-wide | --pid <pid> | -T | [ command [ args ] ] ] .SH DESCRIPTION Operf is the profiler tool provided with OProfile. Operf @@ -248,6 +248,10 @@ A comma-separated list of debugging control values, used to increase the verbosi Valid values are: debug, record, convert, misc, sfile, arcs, or the special value, 'all'. .br .TP +.BI "-T " +Collect the time stamp for each sample. +.br +.TP .BI "--version / -v" Show operf version. .br @@ -267,4 +271,4 @@ $ operf make This man page is current for @PACKAGE@-@VERSION@. .SH SEE ALSO -opreport(1), opannotate(1). +opreport(1), opannotate(1), plot_time_stamps(1). diff --git a/doc/opreport.1.in b/doc/opreport.1.in index 0627aa9..47820b6 100644 --- a/doc/opreport.1.in +++ b/doc/opreport.1.in @@ -144,6 +144,11 @@ Show version. .TP .BI "--xml / -X" Generate XML output. +.TP +.BI "-T " +Print time stamp for each sample. The --xml or -X option must also be +specified as the data is only available in the XML output format. +.br .SH ENVIRONMENT No special environment variables are recognized by opreport. @@ -159,4 +164,4 @@ This man page is current for @PACKAGE@-@VERSION@. .SH SEE ALSO .BR @OP_DOCDIR@, -.BR oprofile(1) +.BR oprofile(1), plot_time_stamps(1). diff --git a/doc/opreport.xsd b/doc/opreport.xsd index 28e3128..5a4301e 100644 --- a/doc/opreport.xsd +++ b/doc/opreport.xsd @@ -207,6 +207,7 @@ <xs:element minOccurs="0" maxOccurs="1" ref="callers"/> <xs:element minOccurs="0" maxOccurs="1" ref="callees"/> <xs:element minOccurs="0" maxOccurs="unbounded" ref="count"/> + <xs:element minOccurs="0" maxOccurs="unbounded" ref="timestamp" use="optional"/> </xs:sequence> <!-- idref is an index into symboltable table--> <xs:attribute name="idref" type="xs:nonNegativeInteger" use="required"/> @@ -246,6 +247,7 @@ <xs:complexType> <xs:sequence> <xs:element minOccurs="1" maxOccurs="unbounded" ref="count"/> + <xs:element minOccurs="0" maxOccurs="unbounded" ref="timestamp" use="optional"/> </xs:sequence> <!-- line only occurs when debug-info option used --> <xs:attribute name="line" type="xs:nonNegativeInteger" use="optional"/> diff --git a/libabi/opimport.cpp b/libabi/opimport.cpp index c2234fe..3d658a7 100644 --- a/libabi/opimport.cpp +++ b/libabi/opimport.cpp @@ -233,7 +233,7 @@ int main(int argc, char const ** argv) cerr << "caught abi exception: " << e.desc << endl; } - odb_close(&dest); + odb_close(&dest, /* write_timestamps*/ false); assert(munmap(in, statb.st_size) == 0); } diff --git a/libabi/tests/abi_test.cpp b/libabi/tests/abi_test.cpp index b129a28..506b345 100644 --- a/libabi/tests/abi_test.cpp +++ b/libabi/tests/abi_test.cpp @@ -91,6 +91,6 @@ int main(int argc, char const ** argv) exit(EXIT_FAILURE); } } - odb_close(&dest); + odb_close(&dest, /* write_timestamps*/ false); } } diff --git a/libdb/db_insert.c b/libdb/db_insert.c index 6bbd71f..6a55d11 100644 --- a/libdb/db_insert.c +++ b/libdb/db_insert.c @@ -16,9 +16,16 @@ #include <errno.h> #include "odb.h" +#include "op_libiberty.h" -static inline int add_node(odb_data_t * data, odb_key_t key, odb_value_t value) +static void insert_timestamp(odb_node_t *node, uint64_t timestamp) { + /* add the time stamp to the head of the list */ + add_data(&node->tm_list, ×tamp, sizeof(uint64_t)); +} + +static inline int add_node(odb_data_t * data, odb_key_t key, odb_value_t value, + uint64_t timestamp) { odb_index_t new_node; odb_node_t * node; @@ -38,6 +45,11 @@ static inline int add_node(odb_data_t * data, odb_key_t key, odb_value_t value) node = &data->node_base[new_node]; node->value = value; node->key = key; + init_buffer(&node->tm_list); + + if (timestamp) { + insert_timestamp(node, timestamp); + } index = odb_do_hash(data, key); node->next = data->hash_base[index]; @@ -49,14 +61,15 @@ static inline int add_node(odb_data_t * data, odb_key_t key, odb_value_t value) return 0; } -int odb_update_node(odb_t * odb, odb_key_t key) +int odb_update_node(odb_t * odb, odb_key_t key, uint64_t timestamp) { - return odb_update_node_with_offset(odb, key, 1); + return odb_update_node_with_offset(odb, key, 1, timestamp); } int odb_update_node_with_offset(odb_t * odb, odb_key_t key, - unsigned long int offset) + unsigned long int offset, + uint64_t timestamp) { odb_index_t index; odb_node_t * node; @@ -69,6 +82,9 @@ int odb_update_node_with_offset(odb_t * odb, if (node->key == key) { if (node->value + offset != 0) { node->value += offset; + if (timestamp) { + insert_timestamp(node, timestamp); + } } else { /* post profile tools must handle overflow */ /* FIXME: the tricky way will be just to add @@ -98,12 +114,12 @@ int odb_update_node_with_offset(odb_t * odb, index = node->next; } - - return add_node(data, key, offset); + /* no existing node, add one */ + return add_node(data, key, offset, timestamp); } int odb_add_node(odb_t * odb, odb_key_t key, odb_value_t value) { - return add_node(odb->data, key, value); + return add_node(odb->data, key, value, /* time stamp */ 0); } diff --git a/libdb/db_manage.c b/libdb/db_manage.c index 668e994..8cb85a4 100644 --- a/libdb/db_manage.c +++ b/libdb/db_manage.c @@ -23,6 +23,7 @@ #include "odb.h" #include "op_string.h" #include "op_libiberty.h" +#include "op_config.h" static __inline odb_descr_t * odb_to_descr(odb_data_t * data) @@ -59,6 +60,43 @@ static unsigned int tables_size(odb_data_t const * data, odb_node_nr_t node_nr) return size; } +/** + * Add space for time stamps after the end of the hash table. + * Call this once after all the samples have been collected and the hash table + * is complete. Note that we are not modifying the hash table itself, and + * we will not rebuild the table after this call is made. + */ +int odb_grow_hashtable_for_timestamps(odb_data_t * data, + unsigned int additional_bytes) +{ + unsigned int old_file_size; + unsigned int new_file_size; + void * new_map; + + old_file_size = tables_size(data, data->descr->size); + new_file_size = old_file_size + additional_bytes; + + if (ftruncate(data->fd, new_file_size)) { + fprintf(stderr, "ERROR odb_grow_hashtable_for_time stamps, ftruncate failed.\n"); + return 1; + } + + new_map = mremap(data->base_memory, + old_file_size, new_file_size, MREMAP_MAYMOVE); + + if (new_map == MAP_FAILED) { + fprintf(stderr, "ERROR odb_grow_hashtable_for_time stamps, mremap failed\n"); + return 1; + } + data->base_memory = new_map; + data->descr = odb_to_descr(data); + data->node_base = odb_to_node_base(data); + data->hash_base = odb_to_hash_base(data); + + /* Note: do not rebuild the hash table. We are not modifying it */ + + return 0; +} int odb_grow_hashtable(odb_data_t * data) { @@ -113,6 +151,15 @@ int odb_grow_hashtable(odb_data_t * data) data->hash_base[index] = pos; } + /* Initialize the values. Entries are updated later if time stamps + * are enabled. + */ + for (pos = data->descr->current_size; pos < data->descr->size; ++pos) { + data->node_base[pos].tm_list.max_size = 0; + data->node_base[pos].tm_list.size = 0; + data->node_base[pos].tm_list.p = NULL; + } + return 0; } @@ -158,6 +205,236 @@ find_samples_data(size_t hash, char const * filename) return NULL; } +/* Read the time stamp data from data->filename. Return the number of + * time stamps for the data file. If no time stamps were collected, + * return zero. +*/ +static int read_timestamp(odb_data_t * data) { + int fd = data->fd; + char *file_name = data->filename; + uint64_t *timestamp_array; + int error = -1; + + uint64_t time_stamp, num_time_stamps, i; + + int n; + int offset, file_size; + int timestamp_size = sizeof(time_stamp); + + file_size = lseek(fd, (off_t) 0L, SEEK_END); + if (file_size <= 0) { + fprintf(stderr, "ERROR, setting fd to end of file %s.\n", + file_name); + error = file_size; + goto err; + } + + /* Back up to right before the number of time stamps and the + * valid time stamp array marker. + */ + offset = file_size - 2 * timestamp_size; + n = lseek(fd, ((off_t) offset), SEEK_SET); + + if (n < 0) { + fprintf(stderr, "ERROR, setting fd to read the number of time stamps " + "in file %s.\n", file_name); + error = n; + goto err; + } + + if ((n = read(fd, &num_time_stamps, sizeof(num_time_stamps))) + != sizeof(num_time_stamps)) { + fprintf(stderr, "ERROR, failed to read enough bytes for the " + "number of time stamps\n"); + error = -1; + goto err; + } + + /* read the end of the time stamp marker */ + if ((n = read(fd, &time_stamp, sizeof(time_stamp))) + != sizeof(time_stamp)) { + fprintf(stderr, "ERROR, failed to read enough bytes for the " + "number of time stamps\n"); + error = -1; + goto err; + } + + if (time_stamp != VALID_TM_ARRAY_END) { + /* We have to abort since the file information is incomplete.*/ + + fprintf(stderr, "\nERROR, operf did not complete writing data correctly to file %s.\n", + file_name); + fprintf(stderr, + "One of the operf processes died unexpectedly.\n\n"); + error = -2; + goto err; + } + + if (num_time_stamps == 0) + timestamp_array = xmalloc(1*sizeof(uint64_t)); + else + timestamp_array = xmalloc(num_time_stamps*sizeof(uint64_t)); + + if (timestamp_array == NULL) { + fprintf(stderr, "ERROR, failed to allocate space for the time stamps " + "stored in file %s\n", file_name); + error = ENOMEM; + goto err; + } + + /* Set the first element to max value. Will be overwritten + * if the file had time stamps. + */ + timestamp_array[0] = EMPTY_TM_ARRAY; + + /* Backup to the beginning of the time stamp array. The layout of the + * data in the file is: + * [hashtable] + * [time stamp data] + * [number of time stamps] + * [time stamp array marker] + */ + offset = file_size - timestamp_size*(num_time_stamps + 2); + + n = lseek(fd, ((off_t) offset), SEEK_SET); + if (n < 0) { + fprintf(stderr, "ERROR, setting fd to read the time stamps in " + "file %s.\n", file_name); + error = n; + goto err; + } + + for (i = 0; i < num_time_stamps; i++) { + if ((n = read(fd, &time_stamp, sizeof(time_stamp))) + != sizeof(num_time_stamps)) { + fprintf(stderr, "ERROR, failed to read enough bytes for " + "time stamp number %ld in file %s\n", i, file_name); + error = n; + goto err; + } + timestamp_array[i] = time_stamp; + } + + /* Calculate the number of bytes used to store the time stamp data and + * number of time stamps and valid marker stored at the end of the file. + */ + data->timestamp_array = timestamp_array; + return ((num_time_stamps+2)*timestamp_size); + err: + return error; +} + +void odb_write_timestamps(odb_t * odb, int data_collector_call) { + /* The output file contains the list of nodes (odb_node_t) that + * contain the key (instruction pointer value), the samples count, + * and a pointer to the list of time stamps. The time stamps for + * each key will all be stored at the end of the data file in the + * array tm_array. Each node will have the index tm_index set + * to the first time stamp for this node in the tm_array. + */ + + odb_data_t * data; + uint64_t index, tm_index = 0, num_timestamps; + odb_node_nr_t pos; + uint64_t value; + void *ptr; + int rc = 0; + int file_size; + + data = odb->data; + + /* This function is called by the operf data collector, the post + * processing tools, and some test functions. Only if we are called + * by the operf data collector will we have time stamps to print. + * We must print the number of time stamps as the last thing in + * the file. This value will be read by the post processor so + * the expected size of the file with the time stamps can be + * calculated. + */ + + if (data_collector_call == 0) + return; + + /* Determine the total number of time stamps to be written to + * the end of the file. Need space for total number of time + * stamps and marker. + */ + num_timestamps = 2; + + for (pos = 1; pos < data->descr->size * BUCKET_FACTOR; pos++) { + num_timestamps += + data->node_base[pos].tm_list.size/sizeof(uint64_t); + } + + /* Grow the hashtable so we can add the time stamps to + * the end of the table. + */ + if (odb_grow_hashtable_for_timestamps(data, + (num_timestamps + * sizeof(uint64_t)))){ + fprintf(stderr, + "ERROR, failed to resize file to write time stamps.\n"); + return; + } + + file_size = lseek(data->fd, 0, SEEK_END); + + /* Make sure the file pointer is pointing at the end + * of the file. + */ + rc = lseek(data->fd, file_size + - num_timestamps*sizeof(uint64_t), SEEK_SET); + + if (rc == (off_t)(-1)) { + fprintf(stderr, "ERROR, failed to reposition file descriptor to write time stamps.\n"); + return; + } + + for (pos = 1; pos < data->descr->size * BUCKET_FACTOR; pos++) { + data->node_base[pos].tm_index = tm_index; + ptr = data->node_base[pos].tm_list.p; + + num_timestamps = data->node_base[pos].tm_list.size/sizeof(uint64_t); + + for (index = 0; index < num_timestamps; index++) { + if( memcpy(&value, ptr, sizeof(uint64_t)) == NULL) { + fprintf(stderr, "ERROR, copy time stamps failed.\n"); + return; + } + rc = write(data->fd, &value, sizeof(value)); + + if (rc < 0) { + fprintf(stderr, "ERROR, write time stamps failed.\n"); + return; + } + ptr += sizeof(uint64_t); + tm_index++; + } + + if ((num_timestamps > 0) && + (data->node_base[pos].value != + (data->node_base[pos].tm_list.size/sizeof(uint64_t)))) { + + fprintf(stderr, "WARNING: missing time stamps " + "for Key = 0x%lx, time stamp count " + " %lu, sample %lu, file %s\n", + (unsigned long int) data->node_base[pos].key, + data->node_base[pos].tm_list.size/sizeof(uint64_t), + (unsigned long int) data->node_base[pos].value, + data->filename); + } + free(data->node_base[pos].tm_list.p); // Done with buffer + } + + /* Write the number of time stamps at the end of the file + * followed by the valid time stamp array marker. + */ + write(data->fd, &tm_index, sizeof(tm_index)); + tm_index = VALID_TM_ARRAY_END; + write(data->fd, &tm_index, sizeof(tm_index)); + + return; +} int odb_open(odb_t * odb, char const * filename, enum odb_rw rw, size_t sizeof_header) @@ -167,6 +444,7 @@ int odb_open(odb_t * odb, char const * filename, enum odb_rw rw, odb_data_t * data; size_t hash; int err = 0; + int timestamp_size; int flags = (rw == ODB_RDWR) ? (O_CREAT | O_RDWR) : O_RDONLY; int mmflags = (rw == ODB_RDWR) ? (PROT_READ | PROT_WRITE) : PROT_READ; @@ -213,9 +491,18 @@ int odb_open(odb_t * odb, char const * filename, enum odb_rw rw, err = errno; goto fail; } + timestamp_size = 0; } else { + /* Time stamp data file exixts */ + data->timestamp_array = NULL; + timestamp_size = read_timestamp(data); + if (timestamp_size < 0) { + err = EIO; /* The data file is bad. */ + goto fail; + } /* Calculate nr node allowing a sanity check later */ - nr_node = (stat_buf.st_size - data->offset_node) / + nr_node = (stat_buf.st_size - timestamp_size + - data->offset_node) / ((sizeof(odb_index_t) * BUCKET_FACTOR) + sizeof(odb_node_t)); } @@ -260,14 +547,17 @@ fail: } -void odb_close(odb_t * odb) +void odb_close(odb_t * odb, int data_collector_call) { odb_data_t * data = odb->data; + size_t size; if (data) { data->ref_count--; if (data->ref_count == 0) { - size_t size = tables_size(data, data->descr->size); + odb_write_timestamps(odb, data_collector_call); + + size = tables_size(data, data->descr->size); list_del(&data->list); munmap(data->base_memory, size); if (data->fd >= 0) diff --git a/libdb/odb.h b/libdb/odb.h index 9ad1da2..52b258a 100644 --- a/libdb/odb.h +++ b/libdb/odb.h @@ -17,6 +17,7 @@ #include <stdint.h> #include "op_list.h" +#include "../libutil/op_growable_buffer.h" /** the type of key. 64-bit because CG needs 32-bit pair {from,to} */ typedef uint64_t odb_key_t; @@ -43,6 +44,8 @@ typedef struct { odb_key_t key; /**< eip */ odb_value_t value; /**< samples count */ odb_index_t next; /**< next entry for this bucket */ + struct growable_buffer tm_list; /* list of time stamps */ + unsigned long int tm_index; /* Index into tm list */ } odb_node_t; /** the minimal information which must be stored in the file to reload @@ -84,6 +87,7 @@ typedef struct odb_data { char * filename; /**< full path name of sample file */ int ref_count; /**< reference count */ struct list_head list; /**< hash bucket list */ + uint64_t *timestamp_array; /* All time stamps for the file */ } odb_data_t; typedef struct { @@ -124,7 +128,7 @@ int odb_open(odb_t * odb, char const * filename, enum odb_rw rw, size_t sizeof_header); /** Close the given ODB file */ -void odb_close(odb_t * odb); +void odb_close(odb_t * odb, int write_timestamp); /** return the number of times this sample file is open */ int odb_open_count(odb_t const * odb); @@ -150,8 +154,15 @@ void odb_sync(odb_t const * odb); * after cleanup some program resource. */ int odb_grow_hashtable(odb_data_t * data); + +/* This call adds space to the end of the table to add the time stamp data. + * This can only be called once, as odb_grow_hashtable() does not know how to + * handle moving the time stamps at the end of the file. + */ +int odb_grow_hashtable_for_timestamp(odb_data_t * data, unsigned int size); + /** - * commit a previously successfull node reservation. This can't fail. + * commit a previously successful node reservation. This can't fail. */ static __inline void odb_commit_reservation(odb_data_t * data) { @@ -178,13 +189,14 @@ void odb_hash_free_stat(odb_hash_stat_t * stats); * * returns EXIT_SUCCESS on success, EXIT_FAILURE on failure */ -int odb_update_node(odb_t * odb, odb_key_t key); +int odb_update_node(odb_t * odb, odb_key_t key, uint64_t timestamp); /** * odb_update_node_with_offset * @param odb the data base object to setup * @param key the hash key * @param offset the offset to be added + * @param timestamp, (user optional) time stamp of sample * * update info at key by adding the specified offset to its associated value, * if the key does not exist a new node is created and the value associated @@ -193,8 +205,9 @@ int odb_update_node(odb_t * odb, odb_key_t key); * returns EXIT_SUCCESS on success, EXIT_FAILURE on failure */ int odb_update_node_with_offset(odb_t * odb, - odb_key_t key, - unsigned long int offset); + odb_key_t key, + unsigned long int offset, + uint64_t timestamp); /** Add a new node w/o regarding if a node with the same key already exists * @@ -232,6 +245,12 @@ odb_do_hash(odb_data_t const * data, odb_key_t value) return ((temp << 0) ^ (temp >> 8)) & data->hash_mask; } +#ifdef DEBUG_TM +extern void print_tmstmp_range(odb_node_t tm_list_node, uint64_t key, + uint64_t *timestmp_array); +extern void print_tmstmp(uint64_t *timestmp_array, uint64_t max); +#endif + #ifdef __cplusplus } #endif diff --git a/libop/op_config.h b/libop/op_config.h index 8fe70c8..f3bed35 100644 --- a/libop/op_config.h +++ b/libop/op_config.h @@ -72,4 +72,6 @@ extern char op_samples_current_dir[]; } #endif +#define EMPTY_TM_ARRAY ~0x0ULL +#define VALID_TM_ARRAY_END 0xA5A5A5A55A5A5A5AULL #endif /* OP_CONFIG_H */ diff --git a/libop/op_xml_out.c b/libop/op_xml_out.c index 63ee41c..4fc3233 100644 --- a/libop/op_xml_out.c +++ b/libop/op_xml_out.c @@ -61,6 +61,7 @@ char const * xml_tag_map[] = { "summarydata", "sampledata", "count", + "timestamp", "detailtable", "symboldetails", "detaildata", diff --git a/libop/op_xml_out.h b/libop/op_xml_out.h index a829f66..cd8c0dc 100644 --- a/libop/op_xml_out.h +++ b/libop/op_xml_out.h @@ -39,6 +39,7 @@ typedef enum { SOURCE_FILE, SOURCE_LINE, CODE_LENGTH, SUMMARY, SAMPLE, COUNT, + TIMESTAMP, DETAIL_TABLE, SYMBOL_DETAILS, DETAIL_DATA, VMA, BYTES_TABLE, BYTES, HELP_EVENTS, diff --git a/libperf_events/operf_counter.cpp b/libperf_events/operf_counter.cpp index 023f210..acd361a 100644 --- a/libperf_events/operf_counter.cpp +++ b/libperf_events/operf_counter.cpp @@ -206,7 +206,8 @@ out: } // end anonymous namespace operf_counter::operf_counter(operf_event_t & evt, bool enable_on_exec, bool do_cg, - bool separate_cpu, bool inherit, int event_number) + bool do_timestamps, bool separate_cpu, + bool inherit, int event_number) { memset(&attr, 0, sizeof(attr)); attr.size = sizeof(attr); @@ -215,6 +216,8 @@ operf_counter::operf_counter(operf_event_t & evt, bool enable_on_exec, bool do_ attr.sample_type |= PERF_SAMPLE_CALLCHAIN; if (separate_cpu) attr.sample_type |= PERF_SAMPLE_CPU; + if (do_timestamps) + attr.sample_type |= PERF_SAMPLE_TIME; #ifdef __s390__ attr.type = PERF_TYPE_HARDWARE; @@ -316,8 +319,9 @@ operf_record::~operf_record() operf_record::operf_record(int out_fd, bool sys_wide, pid_t the_pid, bool pid_running, vector<operf_event_t> & events, vmlinux_info_t vi, bool do_cg, - bool separate_by_cpu, bool out_fd_is_file, - int _convert_read_pipe, int _convert_write_pipe) + bool do_timestamps, bool separate_by_cpu, + bool out_fd_is_file, int _convert_read_pipe, + int _convert_write_pipe) { struct sigaction sa; sigset_t ss; @@ -328,6 +332,7 @@ operf_record::operf_record(int out_fd, bool sys_wide, pid_t the_pid, bool pid_ru pid_started = pid_running; system_wide = sys_wide; callgraph = do_cg; + collect_timestamps = do_timestamps; separate_cpu = separate_by_cpu; total_bytes_recorded = 0; poll_count = 0; @@ -693,7 +698,9 @@ void operf_record::setup() pid_for_open = pid_to_profile; operf_counter op_ctr(operf_counter(evts[event], (!pid_started && !system_wide), - callgraph, separate_cpu, + callgraph, + collect_timestamps, + separate_cpu, inherit, event)); if ((rc = op_ctr.perf_event_open(pid_for_open, real_cpu, this, true)) < 0) { @@ -783,7 +790,8 @@ int operf_record::_start_recoding_new_thread(pid_t id) for (unsigned event = 0; event < evts.size(); event++) { operf_counter op_ctr(operf_counter(evts[event], (!pid_started && !system_wide), - callgraph, separate_cpu, + callgraph, collect_timestamps, + separate_cpu, false, event)); if (op_ctr.perf_event_open(id, -1, this, false) < 0) { sample_id = OP_PERF_NO_SAMPLE_ID; diff --git a/libperf_events/operf_counter.h b/libperf_events/operf_counter.h index 6e19da9..7f41863 100644 --- a/libperf_events/operf_counter.h +++ b/libperf_events/operf_counter.h @@ -57,7 +57,8 @@ op_perf_event_open(struct perf_event_attr * attr, class operf_counter { public: operf_counter(operf_event_t & evt, bool enable_on_exec, bool callgraph, - bool separate_by_cpu, bool inherit, int event_number); + bool collect_timestamps, bool separate_by_cpu, + bool inherit, int event_number); ~operf_counter(); int perf_event_open(pid_t pid, int cpu, operf_record * pr, bool print_error); const struct perf_event_attr * the_attr(void) const { return &attr; } @@ -83,7 +84,8 @@ public: */ operf_record(int output_fd, bool sys_wide, pid_t the_pid, bool pid_running, std::vector<operf_event_t> & evts, OP_perf_utils::vmlinux_info_t vi, - bool callgraph, bool separate_by_cpu, bool output_fd_is_file, + bool callgraph, bool collect_timestamps, + bool separate_by_cpu, bool output_fd_is_file, int _convert_read_pipe, int _convert_write_pipe); ~operf_record(); void recordPerfData(void); @@ -123,6 +125,7 @@ private: bool pid_started; bool system_wide; bool callgraph; + bool collect_timestamps; bool separate_cpu; std::vector<operf_counter> perfCounters; unsigned int total_bytes_recorded; diff --git a/libperf_events/operf_sfile.cpp b/libperf_events/operf_sfile.cpp index 3ffa325..69bb574 100644 --- a/libperf_events/operf_sfile.cpp +++ b/libperf_events/operf_sfile.cpp @@ -363,7 +363,7 @@ void operf_sfile_log_arc(struct operf_transient const * trans) key = to & (0xffffffff); key |= ((uint64_t)from) << 32; - err = odb_update_node(file, key); + err = odb_update_node(file, key, 0); /* do not add time stamps */ if (err) { fprintf(stderr, "%s: %s\n", __FUNCTION__, strerror(err)); abort(); @@ -400,7 +400,9 @@ void operf_sfile_log_sample_count(struct operf_transient const * trans, } err = odb_update_node_with_offset(file, (odb_key_t)pc, - count); + count, + trans->timestamp); + if (err) { fprintf(stderr, "%s: %s\n", __FUNCTION__, strerror(err)); abort(); @@ -419,7 +421,7 @@ static int close_sfile(struct operf_sfile * sf, void * data __attribute__((unuse /* it's OK to close a non-open odb file */ for (i = 0; i < op_nr_events; ++i) - odb_close(&sf->files[i]); + odb_close(&sf->files[i], true); /* write the time stamps */ // TODO: handle extended //opd_ext_operf_sfile_close(sf); diff --git a/libperf_events/operf_sfile.h b/libperf_events/operf_sfile.h index bc00355..ee1f8bc 100644 --- a/libperf_events/operf_sfile.h +++ b/libperf_events/operf_sfile.h @@ -104,6 +104,7 @@ struct operf_transient { bool cg; // TODO: handle extended //void * ext; + u64 timestamp; }; diff --git a/libperf_events/operf_utils.cpp b/libperf_events/operf_utils.cpp index ff972d4..8b88e43 100644 --- a/libperf_events/operf_utils.cpp +++ b/libperf_events/operf_utils.cpp @@ -75,6 +75,7 @@ static inline void clear_trans(struct operf_transient * trans) { trans->tgid = ~0U; trans->cur_procinfo = NULL; + trans->timestamp = 0; } static void __handle_fork_event(event_t * event) @@ -613,6 +614,14 @@ static int __handle_sample_event(event_t * event, u64 sample_type) goto done; } + data.time = 0; /* if time stamp is 0, it will not be recorded */ + /* Only have time stamps if the user requested them */ + if (sample_type & PERF_SAMPLE_TIME) { + data.time = *array; + trans.timestamp = data.time; + array++; + } + data.id = ~0ULL; if (sample_type & PERF_SAMPLE_ID) { data.id = *array; diff --git a/libpp/callgraph_container.cpp b/libpp/callgraph_container.cpp index 2affa8f..92adde8 100644 --- a/libpp/callgraph_container.cpp +++ b/libpp/callgraph_container.cpp @@ -30,6 +30,7 @@ #include "op_sample_file.h" #include "locate_images.h" #include "utility.h" +#include "profile.h" #include <string.h> using namespace std; @@ -150,7 +151,7 @@ public: for (; p_it.first != p_it.second; ++p_it.first) { samples.push_back(make_pair(p_it.first.vma(), - p_it.first.count())); + p_it.first.cnt_struct().count)); } sort(samples.begin(), samples.end(), diff --git a/libpp/format_output.cpp b/libpp/format_output.cpp index 11cd396..9b980f2 100644 --- a/libpp/format_output.cpp +++ b/libpp/format_output.cpp @@ -32,8 +32,15 @@ #include "xml_utils.h" #include "cverb.h" +/* only print warning on missing times stampls once */ +bool warned_no_timestamps = false; + using namespace std; +namespace options { + extern bool enable_timestamps; +} + namespace { @@ -771,6 +778,8 @@ string xml_formatter:: output_symbol_details(symbol_entry const * symb, size_t & detail_index, size_t const lo, size_t const hi) { + bool found_timestamps = false; + if (!has_sample_counts(symb->sample.counts, lo, hi)) return ""; @@ -817,9 +826,24 @@ output_symbol_details(symbol_entry const * symb, // output buffered sample data output_sample_data(str, it->second, p); + if (options::enable_timestamps) + // output time stamp for each sample collected + found_timestamps |= + output_timestamp_data(str, it->second, p); + str << close_element(DETAIL_DATA); } } + + if (!found_timestamps && (options::enable_timestamps) + && (warned_no_timestamps == false)) { + warned_no_timestamps = true; + cerr << "WARNING, Time stamp option -T was specified " + << "for opreport but no time stamp information\nwas " + << "available. \nUse -T option on operf to collect the " + << "time stamp data.\n\n"; + } + return str.str(); } @@ -833,10 +857,27 @@ output_symbol(ostream & out, // output symbol's summary data for each profile class bool got_samples = false; + bool found_timestamps = false; for (size_t p = lo; p <= hi; ++p) { got_samples |= xml_support->output_summary_data(str, symb->sample.counts, p); + + if ((options::enable_timestamps) && !need_details) + /* Check if time stamp information has been stored. */ + found_timestamps |= xml_support->output_tm_data(str, + symb->sample.counts, + symb->sample.count_timestamp, + p); + } + + if ((options::enable_timestamps) && (found_timestamps == false) + && !need_details && (warned_no_timestamps == false)) { + warned_no_timestamps = true; + cerr << "WARNING, Time stamp option -T was specified for " + << "opreport but no time stamp information\nwas " + << "available. \nUse -T option on operf to collect the " + << "time stamp data.\n\n"; } if (!got_samples) @@ -891,10 +932,48 @@ output_sample_data(ostream & out, sample_entry const & sample, size_t pclass) out << open_element(COUNT, true); out << init_attr(CLASS, classes.v[pclass].name); out << close_element(NONE, true); - out << sample.counts[pclass]; + out << dec << sample.counts[pclass]; out << close_element(COUNT); } +bool xml_formatter:: +output_timestamp_data(ostream & out, sample_entry const & sample, + size_t pclass) +{ + bool found_timestamps = false; + + out << open_element(TIMESTAMP, true); + out << init_attr(CLASS, classes.v[pclass].name); + out << close_element(NONE, true); + + /* print the time stamps */ + count_tm_map_t count_timestamp = sample.count_timestamp; + count_tm_map_t::iterator it = count_timestamp.begin(); + + for(; it != count_timestamp.end(); ++it) { + if (it->first == pclass) { + /* found entry */ + int i = 0; + std::vector<uint64_t> it_tm_vector = it->second; + std::vector<uint64_t>::iterator it_tm = it_tm_vector.begin(); + + for(; it_tm != it_tm_vector.end(); ++it_tm) { + found_timestamps = true; + i++; + out << "0x" << hex << *it_tm << " "; + } + break; + } + } + + if (it->first != pclass) { + cerr << "ERROR: xml_formatter::output_time stamp_data() Failed " + << "to find the Time stamp vector for pclass = " + << pclass << endl; + } + out << close_element(TIMESTAMP); + return found_timestamps; +} void xml_formatter:: output_attribute(ostream & out, field_datum const & datum, diff --git a/libpp/format_output.h b/libpp/format_output.h index 6531bdc..636e5dd 100644 --- a/libpp/format_output.h +++ b/libpp/format_output.h @@ -72,6 +72,8 @@ protected: struct counts_t { /// total sample count count_array_t total; + /// time stamps so far + count_tm_map_t total_tm; /// samples so far count_array_t cumulated_samples; /// percentage so far @@ -282,6 +284,9 @@ private: void output_sample_data(std::ostream & out, sample_entry const & sample, size_t count); + bool output_timestamp_data(std::ostream & out, + sample_entry const & sample, size_t count); + /// output attribute in XML void output_attribute(std::ostream & out, field_datum const & datum, format_flags fl, tag_t tag); diff --git a/libpp/op_header.h b/libpp/op_header.h index b0fc48f..3b1d9a2 100644 --- a/libpp/op_header.h +++ b/libpp/op_header.h @@ -14,8 +14,10 @@ #include <iosfwd> #include <string> +#include <vector> #include "op_sample_file.h" +#include <stdint.h> /** * @param h1 sample file header diff --git a/libpp/profile.cpp b/libpp/profile.cpp index be3ff93..0718522 100644 --- a/libpp/profile.cpp +++ b/libpp/profile.cpp @@ -27,6 +27,7 @@ #include "profile.h" #include "op_bfd.h" #include "cverb.h" +#include <vector> using namespace std; @@ -37,22 +38,22 @@ profile_t::profile_t() // static member -count_type profile_t::sample_count(string const & filename) +count_t profile_t::sample_count(string const & filename) { odb_t samples_db; + count_t count_tm; + count_type count = 0; open_sample_file(filename, samples_db); - count_type count = 0; - odb_node_nr_t node_nr, pos; odb_node_t * node = odb_get_iterator(&samples_db, &node_nr); for (pos = 0; pos < node_nr; ++pos) count += node[pos].value; - odb_close(&samples_db); - - return count; + odb_close(&samples_db, /* write time stamps */ false); + count_tm.count = count; + return count_tm; } //static member @@ -92,22 +93,35 @@ void profile_t::add_sample_file(string const & filename) else file_header.reset(new opd_header(head)); + count_type i; odb_node_nr_t node_nr, pos; odb_node_t * node = odb_get_iterator(&samples_db, &node_nr); - for (pos = 0; pos < node_nr; ++pos) { + for (pos = 1; pos < node_nr; ++pos) { /* node node zero not used */ ordered_samples_t::iterator it = ordered_samples.find(node[pos].key); if (it != ordered_samples.end()) { - it->second += node[pos].value; + it->second.count += node[pos].value; } else { + count_t entry; + entry.count = node[pos].value; + + if (samples_db.data->timestamp_array[0] + != EMPTY_TM_ARRAY) + for (i = node[pos].tm_index; + i < node[pos].tm_index + entry.count; + i++) { + + entry.time_stamps.push_back(samples_db.data->timestamp_array[i]); + } + ordered_samples_t::value_type - val(node[pos].key, node[pos].value); + val(node[pos].key, entry); ordered_samples.insert(val); } } - odb_close(&samples_db); + odb_close(&samples_db, /* write time stamps */ false); } @@ -162,6 +176,28 @@ profile_t::samples_range(odb_key_t start, odb_key_t end) const const_iterator(last, start_offset)); } +const count_t profile_t::accumulate(const_iterator const & first, + const_iterator const & last, + uint64_t val) { + /* accumulate the count value and the corresponding time stamps + * if there are any time stamps. + */ + profile_t::const_iterator it; + count_t count_struct; + std::vector <uint64_t> tm_stamps; + + for (it = first; it != last; ++it) { + count_struct = it.cnt_struct(); + val += count_struct.count; + tm_stamps.insert(tm_stamps.end(), + count_struct.time_stamps.begin(), + count_struct.time_stamps.end()); + } + count_struct.count = val; + count_struct.time_stamps = tm_stamps; + return count_struct; +} + profile_t::iterator_pair profile_t::samples_range() const { diff --git a/libpp/profile.h b/libpp/profile.h index 78cda72..0d094fb 100644 --- a/libpp/profile.h +++ b/libpp/profile.h @@ -16,14 +16,25 @@ #include <string> #include <map> #include <iterator> +#include <vector> #include "odb.h" #include "op_types.h" #include "utility.h" +#include <stdint.h> class opd_header; class op_bfd; +/* structure to store the time stamp for each count + * and the total count + */ +typedef struct { + count_type count; + std::vector <uint64_t> time_stamps; +} count_t; + + /** * Class containing a single sample file contents. * i.e. set of count values for VMA offsets for @@ -52,7 +63,7 @@ public: * them. It's placed here so all access to samples files go through * profile_t static or non static member. */ - static count_type sample_count(std::string const & filename); + static count_t sample_count(std::string const & filename); /** * cumulate sample file to our container of samples @@ -82,6 +93,9 @@ public: /// return a pair of iterator for all samples iterator_pair samples_range() const; + const count_t accumulate(const_iterator const & first, + const_iterator const & last, + uint64_t val); private: /// helper for sample_count() and add_sample_file(). All error launch @@ -92,8 +106,9 @@ private: /// copy of the samples file header scoped_ptr<opd_header> file_header; - /// storage type for samples sorted by eip - typedef std::map<odb_key_t, count_type> ordered_samples_t; + /// storage type for samples sorted by eip, {count, time_stamps} + typedef std::map<odb_key_t, count_t> ordered_samples_t; + // typedef std::map<odb_key_t, count_type> ordered_samples_t; /** * Samples are stored in hash table, iterating over hash table don't @@ -140,14 +155,13 @@ namespace std { template <> struct iterator_traits<profile_t::const_iterator> { typedef ptrdiff_t difference_type; - typedef count_type value_type; - typedef count_type * pointer; - typedef count_type & reference; + typedef count_t value_type; + typedef count_t * pointer; + typedef count_t & reference; typedef input_iterator_tag iterator_category; }; } - class profile_t::const_iterator { typedef ordered_samples_t::const_iterator iterator_t; @@ -156,11 +170,11 @@ public: const_iterator(iterator_t it_, u64 start_offset_) : it(it_), start_offset(start_offset_) {} - count_type operator*() const { return it->second; } + count_t operator*() const { return it->second; } const_iterator & operator++() { ++it; return *this; } odb_key_t vma() const { return it->first + start_offset; } - count_type count() const { return **this; } + count_t cnt_struct() const { return **this; } bool operator!=(const_iterator const & rhs) const { return it != rhs.it; diff --git a/libpp/profile_container.cpp b/libpp/profile_container.cpp index dca6fdd..f69102a 100644 --- a/libpp/profile_container.cpp +++ b/libpp/profile_container.cpp @@ -28,6 +28,10 @@ using namespace std; +namespace options { + extern bool timestamps; +} + namespace { struct filename_by_samples { @@ -70,7 +74,7 @@ profile_container::~profile_container() // the symbols/samples are sorted by increasing vma. // the range of sample_entry inside each symbol entry are valid // the samples_by_file_loc member var is correctly setup. -void profile_container::add(profile_t const & profile, +void profile_container::add(profile_t & profile, op_bfd const & abfd, string const & app_name, size_t pclass) { @@ -81,12 +85,14 @@ void profile_container::add(profile_t const & profile, unsigned long long start = 0, end = 0; symbol_entry symb_entry; + count_t count_tm; abfd.get_symbol_range(i, start, end); profile_t::iterator_pair p_it = profile.samples_range(start, end); - count_type count = accumulate(p_it.first, p_it.second, 0ull); + count_tm = profile.accumulate(p_it.first, p_it.second, 0ull); + count_type count = count_tm.count; // skip entries with no samples if (count == 0) @@ -94,8 +100,16 @@ void profile_container::add(profile_t const & profile, sym_count_total += count; symb_entry.sample.counts[pclass] = count; - total_count[pclass] += count; + /* Track the time stamps for the sym_entry counts in a map. + * Note, if not collecting time stamps, the + * count_tm.time_stamps will be empty. + */ + symb_entry.symbol_add_tm(pclass, count_tm.time_stamps); + total_count[pclass] += count; + /* track the time stamps for the entry in total_count[] for + * use in the XML output. + */ symb_entry.size = end - start; symb_entry.name = symbol_names.create(abfd.syms[i].name()); @@ -125,7 +139,10 @@ void profile_container::add(profile_t const & profile, if (cverb << vdebug) { profile_t::iterator_pair summary_it = profile.samples_range(profile.get_offset(), ~0ULL); - count_type module_summary_count = accumulate(summary_it.first, summary_it.second, 0ull); + count_t count_tm = profile.accumulate(summary_it.first, + summary_it.second, 0ull); + count_type module_summary_count = count_tm.count; + if (sym_count_total < module_summary_count) cout << "INFO: Sample counts differ: Module summary count: " << dec << module_summary_count << "; total symbols count: " << sym_count_total @@ -149,7 +166,8 @@ profile_container::add_samples(op_bfd const & abfd, symbol_index_t sym_index, for (it = p_it.first; it != p_it.second ; ++it) { sample_entry sample; - sample.counts[pclass] = it.count(); + sample.counts[pclass] = it.cnt_struct().count; + sample.count_timestamp[pclass] = it.cnt_struct().time_stamps; sample.file_loc.linenr = 0; if (debug_info) { @@ -263,6 +281,11 @@ count_array_t profile_container::samples_count() const return total_count; } +count_tm_map_t profile_container::samples_count_tm() const +{ + return total_tm; +} + // Rest here are delegated to our private implementation. diff --git a/libpp/profile_container.h b/libpp/profile_container.h index c22f5d3..5396c72 100644 --- a/libpp/profile_container.h +++ b/libpp/profile_container.h @@ -63,7 +63,7 @@ public: * Obviously you can add only samples files which are coherent (same * sampling rate, same events etc.) */ - void add(profile_t const & profile, op_bfd const & abfd, + void add(profile_t & profile, op_bfd const & abfd, std::string const & app_name, size_t pclass); /// Find a symbol from its image_name, vma, return zero if no symbol @@ -117,6 +117,9 @@ public: /// return the total number of samples count_array_t samples_count() const; + /// return the time stamp vector for the total number of samples + count_tm_map_t samples_count_tm() const; + /// Get the samples count which belongs to filename. Return 0 if /// no samples found. count_array_t samples_count(debug_name_id filename_id) const; @@ -171,6 +174,9 @@ private: /// build() must count samples count for each profile class so cache it /// here since user of profile_container often need it later. count_array_t total_count; + /// XML output will use the time stamps. + count_tm_map_t total_tm; + /** * Optimization hints for what information we are going to need, diff --git a/libpp/symbol.cpp b/libpp/symbol.cpp index cb39571..f17e25c 100644 --- a/libpp/symbol.cpp +++ b/libpp/symbol.cpp @@ -47,3 +47,10 @@ string const & get_image_name(image_name_id id, { return image_names.get_name(id, type, extra); } + +void symbol_entry::symbol_add_tm(size_t pclass, + std::vector <uint64_t> & time_stamps) +{ + /* add time stamp vector to map with key pclass */ + sample.count_timestamp[pclass] = time_stamps; +} diff --git a/libpp/symbol.h b/libpp/symbol.h index 017e04c..580fea2 100644 --- a/libpp/symbol.h +++ b/libpp/symbol.h @@ -30,6 +30,8 @@ class extra_images; /// for storing sample counts typedef sparse_array<u32, count_type> count_array_t; +/// map for storing the time stamp vector for the counts +typedef std::map<u32, std::vector<uint64_t> > count_tm_map_t; /// A simple container for a fileno:linenr location. struct file_location { @@ -56,6 +58,8 @@ struct sample_entry { bfd_vma vma; /// the samples count count_array_t counts; + /// the time stamps for the samples count + count_tm_map_t count_timestamp; }; @@ -64,6 +68,8 @@ class symbol_entry { public: symbol_entry() : sym_index(0), size(0), vma_adj(0) {} virtual ~symbol_entry() {} + class const_iterator; + typedef std::pair<const_iterator, const_iterator> iterator_pair; /// which image this symbol belongs to image_name_id image_name; @@ -99,6 +105,8 @@ public: * this to every symbol_entry, but there isn't a better option. */ bfd_vma vma_adj; + void symbol_add_tm(size_t pclass, + std::vector <uint64_t> & time_stamps); }; diff --git a/libpp/symbol_container.cpp b/libpp/symbol_container.cpp index 55aa76f..7931864 100644 --- a/libpp/symbol_container.cpp +++ b/libpp/symbol_container.cpp @@ -9,6 +9,7 @@ * @author John Levon */ +#include <iostream> // for debugging only remove later #include <string> #include <algorithm> #include <set> diff --git a/libpp/xml_utils.cpp b/libpp/xml_utils.cpp index 3de41e5..fe5658f 100644 --- a/libpp/xml_utils.cpp +++ b/libpp/xml_utils.cpp @@ -386,7 +386,47 @@ xml_utils::output_symbol_bytes(ostream & out, symbol_entry const * symb, bool -xml_utils::output_summary_data(ostream & out, count_array_t const & summary, size_t pclass) +xml_utils::output_tm_data(std::ostream & out, count_array_t const & summary, + count_tm_map_t const & summary_tm, size_t pclass) +{ + /* Return true if there were time stamps found to print */ + count_tm_map_t tm_map = summary_tm; + count_tm_map_t::iterator it = tm_map.begin(); + bool rtn = false; + + if (summary[pclass] == 0) return false; + + out << open_element(TIMESTAMP, has_subclasses); + + int i = 0; + std::vector<uint64_t> tm_vector; + + for(; it != summary_tm.end(); it++) { + if (it->first == pclass) { + tm_vector = it->second; + break; + } + } + + if (it->first != pclass) { + cerr << "ERROR: xml_utils::output_tm_data failed to find the Time stamp vector for pclass = " << pclass << endl; + } + + std::vector<uint64_t>::iterator it_tm = tm_vector.begin(); + + for(; it_tm != tm_vector.end(); it_tm++) { + i++; + out << "0x" << hex << *it_tm << " "; + rtn = true; + } + + out << close_element(TIMESTAMP); + return rtn; +} + +bool +xml_utils::output_summary_data +(ostream & out, count_array_t const & summary, size_t pclass) { size_t const count = summary[pclass]; @@ -429,6 +469,8 @@ protected: // summary sample data count_array_t summary; + // summary sample data timestamps + count_tm_map_t summary_tm; // range of profile classes approprate for this module size_t lo; @@ -578,6 +620,7 @@ void module_info::output(ostream & out) void module_info::output_summary(ostream & out) { + /* Note, we do not put out time stamp data for the modules */ for (size_t p = lo; p <= hi; ++p) (void)xml_support->output_summary_data(out, summary, p); } diff --git a/libpp/xml_utils.h b/libpp/xml_utils.h index 668e943..7ae27c4 100644 --- a/libpp/xml_utils.h +++ b/libpp/xml_utils.h @@ -48,6 +48,9 @@ public: size_t sym_id, op_bfd const & abfd); bool output_summary_data(std::ostream & out, count_array_t const & summary, size_t pclass); + bool output_tm_data(std::ostream & out, count_array_t const & summary, + count_tm_map_t const & summary_tm, size_t pclass); + size_t get_symbol_index(sym_iterator const it); void output_program_structure(std::ostream & out); void build_subclasses(std::ostream & out); diff --git a/pe_profiling/operf.cpp b/pe_profiling/operf.cpp index 5585b34..dd95ca8 100644 --- a/pe_profiling/operf.cpp +++ b/pe_profiling/operf.cpp @@ -125,6 +125,7 @@ bool system_wide; bool append; int pid; bool callgraph; +bool collect_timestamps; int mmap_pages_mult; string session_dir; string vmlinux; @@ -143,6 +144,7 @@ struct option long_options [] = {"session-dir", required_argument, NULL, 'd'}, {"vmlinux", required_argument, NULL, 'k'}, {"callgraph", no_argument, NULL, 'g'}, + {"timestamps", no_argument, NULL, 'T'}, {"system-wide", no_argument, NULL, 's'}, {"append", no_argument, NULL, 'a'}, {"pid", required_argument, NULL, 'p'}, @@ -156,7 +158,7 @@ struct option long_options [] = {NULL, 9, NULL, 0} }; -const char * short_options = "V:d:k:gsap:e:ctlhuv"; +const char * short_options = "V:d:k:gsaTp:e:ctlhuv"; vector<string> verbose_string; @@ -175,7 +177,7 @@ static void __print_usage_and_exit(const char * extra_msg) { if (extra_msg) cerr << extra_msg << endl; - cerr << "usage: operf [ options ] [ --system-wide | --pid <pid> | [ command [ args ] ] ]" << endl; + cerr << "usage: operf [ options ] [ --system-wide | --pid <pid> | -T | [ command [ args ] ] ]" << endl; cerr << "See operf man page for details." << endl; exit(EXIT_FAILURE); } @@ -374,6 +376,7 @@ int start_profiling(void) operfRecord = new operf_record(outfd, operf_options::system_wide, app_PID, (operf_options::pid == app_PID), events, vi, operf_options::callgraph, + operf_options::collect_timestamps, operf_options::separate_cpu, operf_options::post_conversion, operf_convert_record_write_pipe[0], operf_record_convert_write_pipe[1]); if (operfRecord->get_valid() == false) { @@ -1292,6 +1295,9 @@ static int _process_operf_and_app_args(int argc, char * const argv[]) case 'g': operf_options::callgraph = true; break; + case 'T': + operf_options::collect_timestamps = true; + break; case 's': operf_options::system_wide = true; break; diff --git a/pp/opgprof.cpp b/pp/opgprof.cpp index 6550f21..7907b94 100644 --- a/pp/opgprof.cpp +++ b/pp/opgprof.cpp @@ -122,13 +122,13 @@ void output_cg(FILE * fp, op_bfd const & abfd, profile_t const & cg_db) op_write_u8(fp, GMON_TAG_CG_ARC); op_write_vma(fp, abfd, abfd.offset_to_pc(from + offset)); op_write_vma(fp, abfd, abfd.offset_to_pc(to + offset)); - u32 count = p_it.first.count(); - if (count != p_it.first.count()) { + u32 count = p_it.first.cnt_struct().count; + if (count != p_it.first.cnt_struct().count) { count = (u32)-1; cerr << "Warning: capping sample count by " - << p_it.first.count() - count << endl; + << p_it.first.cnt_struct().count - count << endl; } - op_write_u32(fp, p_it.first.count()); + op_write_u32(fp, p_it.first.cnt_struct().count); } } diff --git a/pp/opreport.cpp b/pp/opreport.cpp index 7ad6190..0135367 100644 --- a/pp/opreport.cpp +++ b/pp/opreport.cpp @@ -64,9 +64,12 @@ add_files(list<profile_sample_files> const & files, size_t pclass) list<profile_sample_files>::const_iterator const end = files.end(); for (; it != end; ++it) { - count_type count = profile_t::sample_count(it->sample_filename); - counts[pclass] += count; - subtotal += count; + count_t count_tm; + count_tm = profile_t::sample_count(it->sample_filename); + + + counts[pclass] += count_tm.count; + subtotal += count_tm.count; if (!it->cg_files.empty()) { throw op_runtime_error("opreport.cpp::add_files(): " diff --git a/pp/opreport_options.cpp b/pp/opreport_options.cpp index bc58e51..931a3d6 100644 --- a/pp/opreport_options.cpp +++ b/pp/opreport_options.cpp @@ -36,6 +36,7 @@ namespace options { demangle_type demangle = dmt_normal; bool symbols; bool callgraph; + bool enable_timestamps; bool debug_info; bool details; bool exclude_dependent; @@ -49,6 +50,7 @@ namespace options { bool reverse_sort; bool global_percent; bool xml; + bool time_stamp; string xml_options; } @@ -65,6 +67,8 @@ string demangle_option = "normal"; popt::option options_array[] = { popt::option(options::callgraph, "callgraph", 'c', "show call graph"), + popt::option(options::enable_timestamps, "enable_timestamps", 'T', + "show timestamps in XML output"), popt::option(options::details, "details", 'd', "output detailed samples for each symbol"), popt::option(options::symbols, "symbols", 'l', @@ -110,6 +114,9 @@ popt::option options_array[] = { popt::option(options::xml, "xml", 'X', "XML output"), + popt::option(options::time_stamp, "T", 'T', + "Time stamp output. Requires the --xml or -X option to be specified as well."), + }; @@ -191,6 +198,13 @@ void check_options(bool diff) } } + if (enable_timestamps && !xml) { + cerr << "--timestamps (-T) only prints the sample " + "time stamps in the XML output file. \nYou must " + "use the --xml option with the time stamp option." + << endl; + do_exit = true; + } if (details && diff) { cerr << "differential profiles are incompatible with --details" << endl; diff --git a/pp/opreport_options.h b/pp/opreport_options.h index 51ab7a6..37288f1 100644 --- a/pp/opreport_options.h +++ b/pp/opreport_options.h @@ -27,6 +27,7 @@ namespace options { extern demangle_type demangle; extern bool symbols; extern bool callgraph; + extern bool enable_timestamps; extern bool debug_info; extern bool details; extern bool reverse_sort; -- 1.7.1 ------------------------------------------------------------------------------