New upstream version 24.0.1+dfsg1

This commit is contained in:
Sebastian Ramacher 2019-09-22 23:19:10 +02:00
parent b14f9eae6d
commit 5a730d6ec3
842 changed files with 42245 additions and 33385 deletions

View file

@ -93,16 +93,16 @@ static inline uint64_t diff_ns_to_usec(uint64_t prev, uint64_t next)
static inline void update_max_probes(profile_times_table *map, size_t val)
{
map->max_probe_count = map->max_probe_count < val ?
val : map->max_probe_count;
map->max_probe_count =
map->max_probe_count < val ? val : map->max_probe_count;
}
static void migrate_old_entries(profile_times_table *map, bool limit_items);
static void grow_hashmap(profile_times_table *map,
uint64_t usec, uint64_t count);
static void grow_hashmap(profile_times_table *map, uint64_t usec,
uint64_t count);
static void add_hashmap_entry(profile_times_table *map, uint64_t usec,
uint64_t count)
uint64_t count)
{
size_t probes = 1;
@ -127,14 +127,14 @@ static void add_hashmap_entry(profile_times_table *map, uint64_t usec,
if (entry->probes >= probes)
continue;
if (map->occupied/(double)map->size > 0.7) {
if (map->occupied / (double)map->size > 0.7) {
grow_hashmap(map, usec, count);
return;
}
size_t old_probes = entry->probes;
uint64_t old_count = entry->entry.count;
uint64_t old_usec = entry->entry.time_delta;
size_t old_probes = entry->probes;
uint64_t old_count = entry->entry.count;
uint64_t old_usec = entry->entry.time_delta;
entry->probes = probes;
entry->entry.count = count;
@ -143,8 +143,8 @@ static void add_hashmap_entry(profile_times_table *map, uint64_t usec,
update_max_probes(map, probes);
probes = old_probes;
count = old_count;
usec = old_usec;
count = old_count;
usec = old_usec;
start = usec % map->size;
}
@ -182,24 +182,24 @@ static void migrate_old_entries(profile_times_table *map, bool limit_items)
continue;
add_hashmap_entry(map, entry->entry.time_delta,
entry->entry.count);
entry->entry.count);
map->old_occupied -= 1;
}
}
static void grow_hashmap(profile_times_table *map,
uint64_t usec, uint64_t count)
static void grow_hashmap(profile_times_table *map, uint64_t usec,
uint64_t count)
{
migrate_old_entries(map, false);
size_t old_size = map->size;
size_t old_size = map->size;
size_t old_occupied = map->occupied;
profile_times_table_entry *entries = map->entries;
init_hashmap(map, (old_size * 2 < 16) ? 16 : (old_size * 2));
map->old_occupied = old_occupied;
map->old_entries = entries;
map->old_entries = entries;
add_hashmap_entry(map, usec, count);
}
@ -229,7 +229,7 @@ static profile_entry *get_child(profile_entry *parent, const char *name)
}
static void merge_call(profile_entry *entry, profile_call *call,
profile_call *prev_call)
profile_call *prev_call)
{
const size_t num = call->children.num;
for (size_t i = 0; i < num; i++) {
@ -240,7 +240,7 @@ static void merge_call(profile_entry *entry, profile_call *call,
if (entry->expected_time_between_calls != 0 && prev_call) {
migrate_old_entries(&entry->times_between_calls, true);
uint64_t usec = diff_ns_to_usec(prev_call->start_time,
call->start_time);
call->start_time);
add_hashmap_entry(&entry->times_between_calls, usec, 1);
}
@ -250,7 +250,7 @@ static void merge_call(profile_entry *entry, profile_call *call,
#ifdef TRACK_OVERHEAD
migrate_old_entries(&entry->overhead, true);
usec = diff_ns_to_usec(call->overhead_start, call->start_time);
usec = diff_ns_to_usec(call->overhead_start, call->start_time);
usec += diff_ns_to_usec(call->end_time, call->overhead_end);
add_hashmap_entry(&entry->overhead, usec, 1);
#endif
@ -324,7 +324,7 @@ static profile_root_entry *get_root_entry(const char *name)
}
void profile_register_root(const char *name,
uint64_t expected_time_between_calls)
uint64_t expected_time_between_calls)
{
if (!lock_root())
return;
@ -349,8 +349,8 @@ static void merge_context(profile_call *context)
profile_root_entry *r_entry = get_root_entry(context->name);
mutex = r_entry->mutex;
entry = r_entry->entry;
mutex = r_entry->mutex;
entry = r_entry->entry;
prev_call = r_entry->prev_call;
r_entry->prev_call = context;
@ -408,12 +408,13 @@ void profile_end(const char *name)
call->name = name;
if (call->name != name) {
blog(LOG_ERROR, "Called profile end with mismatching name: "
"start(\"%s\"[%p]) <-> end(\"%s\"[%p])",
call->name, call->name, name, name);
blog(LOG_ERROR,
"Called profile end with mismatching name: "
"start(\"%s\"[%p]) <-> end(\"%s\"[%p])",
call->name, call->name, name, name);
profile_call *parent = call->parent;
while (parent && parent->parent && parent->name != name)
while (parent && parent->parent && parent->name != name)
parent = parent->parent;
if (!parent || parent->name != name)
@ -440,14 +441,14 @@ void profile_end(const char *name)
static int profiler_time_entry_compare(const void *first, const void *second)
{
int64_t diff = ((profiler_time_entry*)second)->time_delta -
((profiler_time_entry*)first)->time_delta;
int64_t diff = ((profiler_time_entry *)second)->time_delta -
((profiler_time_entry *)first)->time_delta;
return diff < 0 ? -1 : (diff > 0 ? 1 : 0);
}
static uint64_t copy_map_to_array(profile_times_table *map,
profiler_time_entries_t *entry_buffer,
uint64_t *min_, uint64_t *max_)
profiler_time_entries_t *entry_buffer,
uint64_t *min_, uint64_t *max_)
{
migrate_old_entries(map, false);
@ -480,16 +481,18 @@ static uint64_t copy_map_to_array(profile_times_table *map,
}
typedef void (*profile_entry_print_func)(profiler_snapshot_entry_t *entry,
struct dstr *indent_buffer, struct dstr *output_buffer,
unsigned indent, uint64_t active, uint64_t parent_calls);
struct dstr *indent_buffer,
struct dstr *output_buffer,
unsigned indent, uint64_t active,
uint64_t parent_calls);
/* UTF-8 characters */
#define VPIPE_RIGHT " \xe2\x94\xa3"
#define VPIPE " \xe2\x94\x83"
#define DOWN_RIGHT " \xe2\x94\x97"
#define VPIPE " \xe2\x94\x83"
#define DOWN_RIGHT " \xe2\x94\x97"
static void make_indent_string(struct dstr *indent_buffer, unsigned indent,
uint64_t active)
uint64_t active)
{
indent_buffer->len = 0;
@ -505,15 +508,15 @@ static void make_indent_string(struct dstr *indent_buffer, unsigned indent,
fragment = last ? VPIPE_RIGHT : VPIPE;
else
fragment = last ? DOWN_RIGHT : " ";
dstr_cat(indent_buffer, fragment);
}
}
static void gather_stats(uint64_t expected_time_between_calls,
profiler_time_entries_t *entries,
uint64_t calls, uint64_t *percentile99, uint64_t *median,
double *percent_within_bounds)
profiler_time_entries_t *entries, uint64_t calls,
uint64_t *percentile99, uint64_t *median,
double *percent_within_bounds)
{
if (!entries->num) {
*percentile99 = 0;
@ -559,8 +562,9 @@ static void gather_stats(uint64_t expected_time_between_calls,
#define G_MS "g\xC2\xA0ms"
static void profile_print_entry(profiler_snapshot_entry_t *entry,
struct dstr *indent_buffer, struct dstr *output_buffer,
unsigned indent, uint64_t active, uint64_t parent_calls)
struct dstr *indent_buffer,
struct dstr *output_buffer, unsigned indent,
uint64_t active, uint64_t parent_calls)
{
uint64_t calls = entry->overall_count;
uint64_t min_ = entry->min_time;
@ -568,28 +572,26 @@ static void profile_print_entry(profiler_snapshot_entry_t *entry,
uint64_t percentile99 = 0;
uint64_t median = 0;
double percent_within_bounds = 0.;
gather_stats(entry->expected_time_between_calls,
&entry->times, calls,
&percentile99, &median, &percent_within_bounds);
gather_stats(entry->expected_time_between_calls, &entry->times, calls,
&percentile99, &median, &percent_within_bounds);
make_indent_string(indent_buffer, indent, active);
if (min_ == max_) {
dstr_printf(output_buffer, "%s%s: %"G_MS,
indent_buffer->array, entry->name,
min_ / 1000.);
dstr_printf(output_buffer, "%s%s: %" G_MS, indent_buffer->array,
entry->name, min_ / 1000.);
} else {
dstr_printf(output_buffer, "%s%s: min=%"G_MS", median=%"G_MS", "
"max=%"G_MS", 99th percentile=%"G_MS,
indent_buffer->array, entry->name,
min_ / 1000., median / 1000., max_ / 1000.,
percentile99 / 1000.);
dstr_printf(output_buffer,
"%s%s: min=%" G_MS ", median=%" G_MS ", "
"max=%" G_MS ", 99th percentile=%" G_MS,
indent_buffer->array, entry->name, min_ / 1000.,
median / 1000., max_ / 1000., percentile99 / 1000.);
if (entry->expected_time_between_calls) {
double expected_ms =
entry->expected_time_between_calls / 1000.;
dstr_catf(output_buffer, ", %g%% below %"G_MS,
percent_within_bounds, expected_ms);
dstr_catf(output_buffer, ", %g%% below %" G_MS,
percent_within_bounds, expected_ms);
}
}
@ -597,7 +599,7 @@ static void profile_print_entry(profiler_snapshot_entry_t *entry,
double calls_per_parent = (double)calls / parent_calls;
if (lround(calls_per_parent * 10) != 10)
dstr_catf(output_buffer, ", %g calls per parent call",
calls_per_parent);
calls_per_parent);
}
blog(LOG_INFO, "%s", output_buffer->array);
@ -606,16 +608,16 @@ static void profile_print_entry(profiler_snapshot_entry_t *entry,
for (size_t i = 0; i < entry->children.num; i++) {
if ((i + 1) == entry->children.num)
active &= (1 << indent) - 1;
profile_print_entry(&entry->children.array[i],
indent_buffer, output_buffer,
indent + 1, active, calls);
profile_print_entry(&entry->children.array[i], indent_buffer,
output_buffer, indent + 1, active, calls);
}
}
static void gather_stats_between(profiler_time_entries_t *entries,
uint64_t calls, uint64_t lower_bound, uint64_t upper_bound,
uint64_t min_, uint64_t max_, uint64_t *median,
double *percent, double *lower, double *higher)
uint64_t calls, uint64_t lower_bound,
uint64_t upper_bound, uint64_t min_,
uint64_t max_, uint64_t *median,
double *percent, double *lower, double *higher)
{
*median = 0;
*percent = 0.;
@ -679,8 +681,10 @@ static void gather_stats_between(profiler_time_entries_t *entries,
}
static void profile_print_entry_expected(profiler_snapshot_entry_t *entry,
struct dstr *indent_buffer, struct dstr *output_buffer,
unsigned indent, uint64_t active, uint64_t parent_calls)
struct dstr *indent_buffer,
struct dstr *output_buffer,
unsigned indent, uint64_t active,
uint64_t parent_calls)
{
UNUSED_PARAMETER(parent_calls);
@ -696,33 +700,31 @@ static void profile_print_entry_expected(profiler_snapshot_entry_t *entry,
double lower = 0.;
double higher = 0.;
gather_stats_between(&entry->times_between_calls,
entry->overall_between_calls_count,
(uint64_t)(expected_time * 0.98),
(uint64_t)(expected_time * 1.02 + 0.5),
min_, max_,
&median, &percent, &lower, &higher);
entry->overall_between_calls_count,
(uint64_t)(expected_time * 0.98),
(uint64_t)(expected_time * 1.02 + 0.5), min_, max_,
&median, &percent, &lower, &higher);
make_indent_string(indent_buffer, indent, active);
blog(LOG_INFO, "%s%s: min=%"G_MS", median=%"G_MS", max=%"G_MS", %g%% "
"within ±2%% of %"G_MS" (%g%% lower, %g%% higher)",
indent_buffer->array, entry->name,
min_ / 1000., median / 1000., max_ / 1000., percent,
expected_time / 1000.,
lower, higher);
blog(LOG_INFO,
"%s%s: min=%" G_MS ", median=%" G_MS ", max=%" G_MS ", %g%% "
"within ±2%% of %" G_MS " (%g%% lower, %g%% higher)",
indent_buffer->array, entry->name, min_ / 1000., median / 1000.,
max_ / 1000., percent, expected_time / 1000., lower, higher);
active |= (uint64_t)1 << indent;
for (size_t i = 0; i < entry->children.num; i++) {
if ((i + 1) == entry->children.num)
active &= (1 << indent) - 1;
profile_print_entry_expected(&entry->children.array[i],
indent_buffer, output_buffer,
indent + 1, active, 0);
indent_buffer, output_buffer,
indent + 1, active, 0);
}
}
void profile_print_func(const char *intro, profile_entry_print_func print,
profiler_snapshot_t *snap)
profiler_snapshot_t *snap)
{
struct dstr indent_buffer = {0};
struct dstr output_buffer = {0};
@ -733,8 +735,8 @@ void profile_print_func(const char *intro, profile_entry_print_func print,
blog(LOG_INFO, "%s", intro);
for (size_t i = 0; i < snap->roots.num; i++) {
print(&snap->roots.array[i],
&indent_buffer, &output_buffer, 0, 0, 0);
print(&snap->roots.array[i], &indent_buffer, &output_buffer, 0,
0, 0);
}
blog(LOG_INFO, "=================================================");
@ -748,13 +750,13 @@ void profile_print_func(const char *intro, profile_entry_print_func print,
void profiler_print(profiler_snapshot_t *snap)
{
profile_print_func("== Profiler Results =============================",
profile_print_entry, snap);
profile_print_entry, snap);
}
void profiler_print_time_between_calls(profiler_snapshot_t *snap)
{
profile_print_func("== Profiler Time Between Calls ==================",
profile_print_entry_expected, snap);
profile_print_entry_expected, snap);
}
static void free_call_children(profile_call *call)
@ -825,19 +827,18 @@ void profiler_free(void)
da_free(old_root_entries);
}
/* ------------------------------------------------------------------------- */
/* Profiler name storage */
struct profiler_name_store {
pthread_mutex_t mutex;
DARRAY(char*) names;
DARRAY(char *) names;
};
profiler_name_store_t *profiler_name_store_create(void)
{
profiler_name_store_t *store = bzalloc(sizeof(profiler_name_store_t));
if (pthread_mutex_init(&store->mutex, NULL))
goto error;
@ -860,8 +861,8 @@ void profiler_name_store_free(profiler_name_store_t *store)
bfree(store);
}
const char *profile_store_name(profiler_name_store_t *store,
const char *format, ...)
const char *profile_store_name(profiler_name_store_t *store, const char *format,
...)
{
va_list args;
va_start(args, format);
@ -881,44 +882,41 @@ const char *profile_store_name(profiler_name_store_t *store,
return result;
}
/* ------------------------------------------------------------------------- */
/* Profiler data access */
static void add_entry_to_snapshot(profile_entry *entry,
profiler_snapshot_entry_t *s_entry)
profiler_snapshot_entry_t *s_entry)
{
s_entry->name = entry->name;
s_entry->overall_count = copy_map_to_array(&entry->times,
&s_entry->times,
&s_entry->min_time, &s_entry->max_time);
s_entry->overall_count =
copy_map_to_array(&entry->times, &s_entry->times,
&s_entry->min_time, &s_entry->max_time);
if ((s_entry->expected_time_between_calls =
entry->expected_time_between_calls))
if ((s_entry->expected_time_between_calls =
entry->expected_time_between_calls))
s_entry->overall_between_calls_count =
copy_map_to_array(&entry->times_between_calls,
&s_entry->times_between_calls,
&s_entry->min_time_between_calls,
&s_entry->max_time_between_calls);
&s_entry->times_between_calls,
&s_entry->min_time_between_calls,
&s_entry->max_time_between_calls);
da_reserve(s_entry->children, entry->children.num);
for (size_t i = 0; i < entry->children.num; i++)
add_entry_to_snapshot(&entry->children.array[i],
da_push_back_new(s_entry->children));
da_push_back_new(s_entry->children));
}
static void sort_snapshot_entry(profiler_snapshot_entry_t *entry)
{
qsort(entry->times.array, entry->times.num,
sizeof(profiler_time_entry),
profiler_time_entry_compare);
qsort(entry->times.array, entry->times.num, sizeof(profiler_time_entry),
profiler_time_entry_compare);
if (entry->expected_time_between_calls)
qsort(entry->times_between_calls.array,
entry->times_between_calls.num,
sizeof(profiler_time_entry),
profiler_time_entry_compare);
entry->times_between_calls.num,
sizeof(profiler_time_entry), profiler_time_entry_compare);
for (size_t i = 0; i < entry->children.num; i++)
sort_snapshot_entry(&entry->children.array[i]);
@ -933,7 +931,7 @@ profiler_snapshot_t *profile_snapshot_create(void)
for (size_t i = 0; i < root_entries.num; i++) {
pthread_mutex_lock(root_entries.array[i].mutex);
add_entry_to_snapshot(root_entries.array[i].entry,
da_push_back_new(snap->roots));
da_push_back_new(snap->roots));
pthread_mutex_unlock(root_entries.array[i].mutex);
}
pthread_mutex_unlock(&root_mutex);
@ -968,48 +966,50 @@ void profile_snapshot_free(profiler_snapshot_t *snap)
typedef void (*dump_csv_func)(void *data, struct dstr *buffer);
static void entry_dump_csv(struct dstr *buffer,
const profiler_snapshot_entry_t *parent,
const profiler_snapshot_entry_t *entry,
dump_csv_func func, void *data)
const profiler_snapshot_entry_t *parent,
const profiler_snapshot_entry_t *entry,
dump_csv_func func, void *data)
{
const char *parent_name = parent ? parent->name : NULL;
for (size_t i = 0; i < entry->times.num; i++) {
dstr_printf(buffer, "%p,%p,%p,%p,%s,0,"
"%"PRIu64",%"PRIu64"\n", entry,
parent, entry->name, parent_name, entry->name,
entry->times.array[i].time_delta,
entry->times.array[i].count);
dstr_printf(buffer,
"%p,%p,%p,%p,%s,0,"
"%" PRIu64 ",%" PRIu64 "\n",
entry, parent, entry->name, parent_name,
entry->name, entry->times.array[i].time_delta,
entry->times.array[i].count);
func(data, buffer);
}
for (size_t i = 0; i < entry->times_between_calls.num; i++) {
dstr_printf(buffer,"%p,%p,%p,%p,%s,"
"%"PRIu64",%"PRIu64",%"PRIu64"\n", entry,
parent, entry->name, parent_name, entry->name,
entry->expected_time_between_calls,
entry->times_between_calls.array[i].time_delta,
entry->times_between_calls.array[i].count);
dstr_printf(buffer,
"%p,%p,%p,%p,%s,"
"%" PRIu64 ",%" PRIu64 ",%" PRIu64 "\n",
entry, parent, entry->name, parent_name,
entry->name, entry->expected_time_between_calls,
entry->times_between_calls.array[i].time_delta,
entry->times_between_calls.array[i].count);
func(data, buffer);
}
for (size_t i = 0; i < entry->children.num; i++)
entry_dump_csv(buffer, entry, &entry->children.array[i],
func, data);
entry_dump_csv(buffer, entry, &entry->children.array[i], func,
data);
}
static void profiler_snapshot_dump(const profiler_snapshot_t *snap,
dump_csv_func func, void *data)
dump_csv_func func, void *data)
{
struct dstr buffer = {0};
dstr_init_copy(&buffer, "id,parent_id,name_id,parent_name_id,name,"
"time_between_calls,time_delta_µs,count\n");
"time_between_calls,time_delta_µs,count\n");
func(data, &buffer);
for (size_t i = 0; i < snap->roots.num; i++)
entry_dump_csv(&buffer, NULL,
&snap->roots.array[i], func, data);
entry_dump_csv(&buffer, NULL, &snap->roots.array[i], func,
data);
dstr_free(&buffer);
}
@ -1020,7 +1020,7 @@ static void dump_csv_fwrite(void *data, struct dstr *buffer)
}
bool profiler_snapshot_dump_csv(const profiler_snapshot_t *snap,
const char *filename)
const char *filename)
{
FILE *f = os_fopen(filename, "wb+");
if (!f)
@ -1038,7 +1038,7 @@ static void dump_csv_gzwrite(void *data, struct dstr *buffer)
}
bool profiler_snapshot_dump_csv_gz(const profiler_snapshot_t *snap,
const char *filename)
const char *filename)
{
gzFile gz;
#ifdef _WIN32
@ -1068,7 +1068,8 @@ size_t profiler_snapshot_num_roots(profiler_snapshot_t *snap)
}
void profiler_snapshot_enumerate_roots(profiler_snapshot_t *snap,
profiler_entry_enum_func func, void *context)
profiler_entry_enum_func func,
void *context)
{
if (!snap)
return;
@ -1079,7 +1080,7 @@ void profiler_snapshot_enumerate_roots(profiler_snapshot_t *snap,
}
void profiler_snapshot_filter_roots(profiler_snapshot_t *snap,
profiler_name_filter_func func, void *data)
profiler_name_filter_func func, void *data)
{
for (size_t i = 0; i < snap->roots.num;) {
bool remove = false;
@ -1104,7 +1105,8 @@ size_t profiler_snapshot_num_children(profiler_snapshot_entry_t *entry)
}
void profiler_snapshot_enumerate_children(profiler_snapshot_entry_t *entry,
profiler_entry_enum_func func, void *context)
profiler_entry_enum_func func,
void *context)
{
if (!entry)
return;
@ -1119,14 +1121,13 @@ const char *profiler_snapshot_entry_name(profiler_snapshot_entry_t *entry)
return entry ? entry->name : NULL;
}
profiler_time_entries_t *profiler_snapshot_entry_times(
profiler_snapshot_entry_t *entry)
profiler_time_entries_t *
profiler_snapshot_entry_times(profiler_snapshot_entry_t *entry)
{
return entry ? &entry->times : NULL;
}
uint64_t profiler_snapshot_entry_overall_count(
profiler_snapshot_entry_t *entry)
uint64_t profiler_snapshot_entry_overall_count(profiler_snapshot_entry_t *entry)
{
return entry ? entry->overall_count : 0;
}
@ -1141,32 +1142,32 @@ uint64_t profiler_snapshot_entry_max_time(profiler_snapshot_entry_t *entry)
return entry ? entry->max_time : 0;
}
profiler_time_entries_t *profiler_snapshot_entry_times_between_calls(
profiler_snapshot_entry_t *entry)
profiler_time_entries_t *
profiler_snapshot_entry_times_between_calls(profiler_snapshot_entry_t *entry)
{
return entry ? &entry->times_between_calls : NULL;
}
uint64_t profiler_snapshot_entry_expected_time_between_calls(
profiler_snapshot_entry_t *entry)
profiler_snapshot_entry_t *entry)
{
return entry ? entry->expected_time_between_calls : 0;
}
uint64_t profiler_snapshot_entry_min_time_between_calls(
profiler_snapshot_entry_t *entry)
uint64_t
profiler_snapshot_entry_min_time_between_calls(profiler_snapshot_entry_t *entry)
{
return entry ? entry->min_time_between_calls : 0;
}
uint64_t profiler_snapshot_entry_max_time_between_calls(
profiler_snapshot_entry_t *entry)
uint64_t
profiler_snapshot_entry_max_time_between_calls(profiler_snapshot_entry_t *entry)
{
return entry ? entry->max_time_between_calls : 0;
}
uint64_t profiler_snapshot_entry_overall_between_calls_count(
profiler_snapshot_entry_t *entry)
profiler_snapshot_entry_t *entry)
{
return entry ? entry->overall_between_calls_count : 0;
}