From patchwork Fri Nov 9 19:50:24 2018 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Yordan Karadzhov X-Patchwork-Id: 10759737 Return-Path: Received: from mail-cys01nam02on0082.outbound.protection.outlook.com ([104.47.37.82]:58643 "EHLO NAM02-CY1-obe.outbound.protection.outlook.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1725752AbeKJFdL (ORCPT ); Sat, 10 Nov 2018 00:33:11 -0500 From: Yordan Karadzhov To: "rostedt@goodmis.org" CC: "linux-trace-devel@vger.kernel.org" Subject: [PATCH v2 1/8] kernel-shark-qt: Reset the second pass hash when reloading Sched plugin Date: Fri, 9 Nov 2018 19:50:24 +0000 Message-ID: <20181109195004.25455-2-ykaradzhov@vmware.com> References: <20181109195004.25455-1-ykaradzhov@vmware.com> In-Reply-To: <20181109195004.25455-1-ykaradzhov@vmware.com> Content-Language: en-US MIME-Version: 1.0 Sender: linux-trace-devel-owner@vger.kernel.org List-ID: Content-Length: 3139 When the plugin is reloaded, the trace data gets reloaded as well. Hence the second pass over the data has to be repeated. Signed-off-by: Yordan Karadzhov --- kernel-shark-qt/src/plugins/SchedEvents.cpp | 15 ++++++--------- kernel-shark-qt/src/plugins/sched_events.c | 4 ++++ kernel-shark-qt/src/plugins/sched_events.h | 3 +++ 3 files changed, 13 insertions(+), 9 deletions(-) diff --git a/kernel-shark-qt/src/plugins/SchedEvents.cpp b/kernel-shark-qt/src/plugins/SchedEvents.cpp index 7f75baa..5f833df 100644 --- a/kernel-shark-qt/src/plugins/SchedEvents.cpp +++ b/kernel-shark-qt/src/plugins/SchedEvents.cpp @@ -193,8 +193,6 @@ static void pluginDraw(plugin_sched_context *plugin_ctx, return; } -static std::unordered_set secondPassDone; - /* * Ideally, the sched_switch has to be the last trace event recorded before the * task is preempted. Because of this, when the data is loaded (the first pass), @@ -250,8 +248,6 @@ static void secondPass(kshark_entry **data, } } } - - secondPassDone.insert(pid); } /** @@ -298,12 +294,13 @@ void plugin_draw(kshark_cpp_argv *argv_c, int pid, int draw_action) KS_TASK_COLLECTION_MARGIN); } - try { - if (secondPassDone.find(pid) == secondPassDone.end()) { - /* The second pass for this task is not done yet. */ - secondPass(argvCpp->_histo->data, col, pid); - } + if (!tracecmd_filter_id_find(plugin_ctx->second_pass_hash, pid)) { + /* The second pass for this task is not done yet. */ + secondPass(argvCpp->_histo->data, col, pid); + tracecmd_filter_id_add(plugin_ctx->second_pass_hash, pid); + } + try { pluginDraw(plugin_ctx, kshark_ctx, argvCpp->_histo, col, SchedEvent::Switch, pid, diff --git a/kernel-shark-qt/src/plugins/sched_events.c b/kernel-shark-qt/src/plugins/sched_events.c index 80ac214..f23c916 100644 --- a/kernel-shark-qt/src/plugins/sched_events.c +++ b/kernel-shark-qt/src/plugins/sched_events.c @@ -79,6 +79,8 @@ static bool plugin_sched_init_context(struct kshark_context *kshark_ctx) plugin_ctx->sched_wakeup_new_success_field = tep_find_field(event, "success"); + plugin_ctx->second_pass_hash = tracecmd_filter_id_hash_alloc(); + return true; } @@ -279,6 +281,8 @@ static int plugin_sched_close(struct kshark_context *kshark_ctx) plugin_sched_action, plugin_draw); + tracecmd_filter_id_hash_free(plugin_ctx->second_pass_hash); + free(plugin_ctx); plugin_sched_context_handler = NULL; diff --git a/kernel-shark-qt/src/plugins/sched_events.h b/kernel-shark-qt/src/plugins/sched_events.h index 5a9406b..481413f 100644 --- a/kernel-shark-qt/src/plugins/sched_events.h +++ b/kernel-shark-qt/src/plugins/sched_events.h @@ -55,6 +55,9 @@ struct plugin_sched_context { * Pointer to the sched_wakeup_new_success_field format descriptor. */ struct tep_format_field *sched_wakeup_new_success_field; + + /** Hash of the tasks for which the second pass is already done. */ + struct tracecmd_filter_id *second_pass_hash; }; int plugin_get_next_pid(struct tep_record *record); From patchwork Fri Nov 9 19:50:25 2018 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Yordan Karadzhov X-Patchwork-Id: 10759729 Return-Path: Received: from mail-cys01nam02on0088.outbound.protection.outlook.com ([104.47.37.88]:36407 "EHLO NAM02-CY1-obe.outbound.protection.outlook.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1725872AbeKJFdB (ORCPT ); Sat, 10 Nov 2018 00:33:01 -0500 From: Yordan Karadzhov To: "rostedt@goodmis.org" CC: "linux-trace-devel@vger.kernel.org" Subject: [PATCH v2 2/8] kernel-shark-qt: Improve the plotting logic of the Sched event plugin Date: Fri, 9 Nov 2018 19:50:25 +0000 Message-ID: <20181109195004.25455-3-ykaradzhov@vmware.com> References: <20181109195004.25455-1-ykaradzhov@vmware.com> In-Reply-To: <20181109195004.25455-1-ykaradzhov@vmware.com> Content-Language: en-US MIME-Version: 1.0 Sender: linux-trace-devel-owner@vger.kernel.org List-ID: Content-Length: 14315 This patch aims to make the plotting logic of the Sched event plugin more robust and easy to understand. It also provides a proper processing of the case when we have multiple Sched events in one bin. The red box showing the time the task was preempted is open only if the prev_state of the sched_switch event is "R". Signed-off-by: Yordan Karadzhov --- kernel-shark-qt/src/plugins/SchedEvents.cpp | 160 +++++++++----------- kernel-shark-qt/src/plugins/sched_events.c | 61 ++++++-- kernel-shark-qt/src/plugins/sched_events.h | 15 +- 3 files changed, 132 insertions(+), 104 deletions(-) diff --git a/kernel-shark-qt/src/plugins/SchedEvents.cpp b/kernel-shark-qt/src/plugins/SchedEvents.cpp index 5f833df..eec60fe 100644 --- a/kernel-shark-qt/src/plugins/SchedEvents.cpp +++ b/kernel-shark-qt/src/plugins/SchedEvents.cpp @@ -54,9 +54,11 @@ static void pluginDraw(plugin_sched_context *plugin_ctx, KsPlot::Graph *graph, KsPlot::PlotObjList *shapes) { + const kshark_entry *entryClose, *entryOpen; std::function ifSchedBack; KsPlot::Rectangle *rec = nullptr; int height = graph->getHeight() * .3; + ssize_t indexClose(0), indexOpen(0); auto openBox = [&] (const KsPlot::Point &p) { @@ -67,7 +69,16 @@ static void pluginDraw(plugin_sched_context *plugin_ctx, if (!rec) rec = new KsPlot::Rectangle; + if (e == SchedEvent::Switch) { + /* Red box. */ + rec->_color = KsPlot::Color(255, 0, 0); + } else { + /* Green box. */ + rec->_color = KsPlot::Color(0, 255, 0); + } + rec->setFill(false); + rec->setPoint(0, p.x() - 1, p.y() - height); rec->setPoint(1, p.x() - 1, p.y() - 1); }; @@ -77,7 +88,7 @@ static void pluginDraw(plugin_sched_context *plugin_ctx, if (rec == nullptr) return; - int boxSize = rec->getPoint(0)->x; + int boxSize = p.x() - rec->getPoint(0)->x; if (boxSize < PLUGIN_MIN_BOX_SIZE) { /* This box is too small. Don't try to plot it. */ delete rec; @@ -92,99 +103,78 @@ static void pluginDraw(plugin_sched_context *plugin_ctx, rec = nullptr; }; - auto lamIfSchSwitchFront = [&] (int bin) - { - /* - * Starting from the first element in this bin, go forward - * in time until you find a trace entry that satisfies the - * condition defined by kshark_match_pid. + for (int bin = 0; bin < graph->size(); ++bin) { + /** + * Plotting the latencies makes sense only in the case of a + * deep zoom. Here we set a naive threshold based on the number + * of entries inside the current bin. This cut seems to work + * well in all cases I tested so far, but it may result in + * unexpected behavior with some unusual trace data-sets. + * TODO: find a better criteria for deciding when to start + * plotting latencies. */ - const kshark_entry *entryF = - ksmodel_get_entry_front(histo, bin, false, - kshark_match_pid, pid, - col, nullptr); - - if (entryF && - entryF->pid == pid && - plugin_ctx->sched_switch_event && - entryF->event_id == plugin_ctx->sched_switch_event->id) { - /* - * entryF is sched_switch_event. Close the box and add - * it to the list of shapes to be ploted. - */ - closeBox(graph->getBin(bin)._base); + if (ksmodel_bin_count(histo, bin) > PLUGIN_MAX_ENTRIES_PER_BIN) { + if (rec) { + delete rec; + rec = nullptr; + } + + continue; } - }; - auto lamIfSchWakeupBack = [&] (int bin) - { /* - * Starting from the last element in this bin, go backward + * Starting from the first element in this bin, go forward * in time until you find a trace entry that satisfies the - * condition defined by plugin_wakeup_match_pid. + * condition defined by kshark_match_pid. */ - const kshark_entry *entryB = - ksmodel_get_entry_back(histo, bin, false, - plugin_wakeup_match_pid, pid, - col, nullptr); + entryClose = ksmodel_get_entry_back(histo, bin, false, + plugin_switch_match_entry_pid, + pid, col, &indexClose); - if (entryB) { + if (e == SchedEvent::Switch) { /* - * entryB is a sched_wakeup_event. Open a - * green box here. + * Starting from the last element in this bin, go backward + * in time until you find a trace entry that satisfies the + * condition defined by plugin_switch_match_pid. */ - openBox(graph->getBin(bin)._base); - - /* Green */ - rec->_color = KsPlot::Color(0, 255, 0); - } - }; - - auto lamIfSchSwitchBack = [&] (int bin) - { - /* - * Starting from the last element in this bin, go backward - * in time until you find a trace entry that satisfies the - * condition defined by plugin_switch_match_pid. - */ - const kshark_entry *entryB = - ksmodel_get_entry_back(histo, bin, false, - plugin_switch_match_pid, pid, - col, nullptr); + entryOpen = + ksmodel_get_entry_back(histo, bin, false, + plugin_switch_match_rec_pid, + pid, col, &indexOpen); - if (entryB && entryB->pid != pid) { + } else { /* - * entryB is a sched_switch_event. Open a - * red box here. + * Starting from the last element in this bin, go backward + * in time until you find a trace entry that satisfies the + * condition defined by plugin_wakeup_match_pid. */ - openBox(graph->getBin(bin)._base); - - /* Red */ - rec->_color = KsPlot::Color(255, 0, 0); + entryOpen = + ksmodel_get_entry_back(histo, bin, false, + plugin_wakeup_match_rec_pid, + pid, col, &indexOpen); } - }; - - if (e == SchedEvent::Switch) - ifSchedBack = lamIfSchSwitchBack; - else - ifSchedBack = lamIfSchWakeupBack; - for (int bin = 0; bin < graph->size(); ++bin) { - /** - * Plotting the latencies makes sense only in the case of a - * deep zoom. Here we set a naive threshold based on the number - * of entries inside the current bin. This cut seems to work - * well in all cases I tested so far, but it may result in - * unexpected behavior with some unusual trace data-sets. - * TODO: find a better criteria for deciding when to start - * plotting latencies. - */ - if (ksmodel_bin_count(histo, bin) > PLUGIN_MAX_ENTRIES_PER_BIN) - continue; - - lamIfSchSwitchFront(bin); - - ifSchedBack(bin); + if (rec) { + if (entryClose) { + /* Close the box in this bin. */ + closeBox(graph->getBin(bin)._base); + if (entryOpen && indexClose < indexOpen) { + /* + * We have a Sched switch entry that + * comes after (in time) the closure of + * the previous box. We have to open a + * new box in this bin. + */ + openBox(graph->getBin(bin)._base); + } + } + } else { + if (entryOpen && + (!entryClose || indexClose < indexOpen)) { + /* Open a new box in this bin. */ + openBox(graph->getBin(bin)._base); + } + } } if (rec) @@ -221,7 +211,8 @@ static void secondPass(kshark_entry **data, kshark_entry_request *req = kshark_entry_request_alloc(first, n, - plugin_switch_match_pid, pid, + plugin_switch_match_rec_pid, + pid, false, KS_GRAPH_VIEW_FILTER_MASK); @@ -256,9 +247,6 @@ static void secondPass(kshark_entry **data, * @param argv_c: A C pointer to be converted to KsCppArgV (C++ struct). * @param pid: Process Id. * @param draw_action: Draw action identifier. - * - * @returns True if the Pid of the entry matches the value of "pid". - * Otherwise false. */ void plugin_draw(kshark_cpp_argv *argv_c, int pid, int draw_action) { @@ -303,12 +291,12 @@ void plugin_draw(kshark_cpp_argv *argv_c, int pid, int draw_action) try { pluginDraw(plugin_ctx, kshark_ctx, argvCpp->_histo, col, - SchedEvent::Switch, pid, + SchedEvent::Wakeup, pid, argvCpp->_graph, argvCpp->_shapes); pluginDraw(plugin_ctx, kshark_ctx, argvCpp->_histo, col, - SchedEvent::Wakeup, pid, + SchedEvent::Switch, pid, argvCpp->_graph, argvCpp->_shapes); } catch (const std::exception &exc) { std::cerr << "Exception in SchedEvents\n" << exc.what(); diff --git a/kernel-shark-qt/src/plugins/sched_events.c b/kernel-shark-qt/src/plugins/sched_events.c index f23c916..1851569 100644 --- a/kernel-shark-qt/src/plugins/sched_events.c +++ b/kernel-shark-qt/src/plugins/sched_events.c @@ -55,6 +55,9 @@ static bool plugin_sched_init_context(struct kshark_context *kshark_ctx) plugin_ctx->sched_switch_comm_field = tep_find_field(event, "next_comm"); + plugin_ctx->sched_switch_prev_state_field = + tep_find_field(event, "prev_state"); + event = tep_find_event_by_name(plugin_ctx->pevent, "sched", "sched_wakeup"); if (!event) @@ -105,7 +108,7 @@ int plugin_get_next_pid(struct tep_record *record) * * @param record: Input location for a sched_wakeup record. */ -int plugin_get_wakeup_pid(struct tep_record *record) +int plugin_get_rec_wakeup_pid(struct tep_record *record) { struct plugin_sched_context *plugin_ctx = plugin_sched_context_handler; @@ -137,7 +140,7 @@ static void plugin_register_command(struct kshark_context *kshark_ctx, tep_register_comm(kshark_ctx->pevent, comm, pid); } -static int plugin_get_wakeup_new_pid(struct tep_record *record) +static int plugin_get_rec_wakeup_new_pid(struct tep_record *record) { struct plugin_sched_context *plugin_ctx = plugin_sched_context_handler; @@ -157,12 +160,12 @@ static int plugin_get_wakeup_new_pid(struct tep_record *record) * @param e: kshark_entry to be checked. * @param pid: Matching condition value. * - * @returns True if the Pid of the entry matches the value of "pid". + * @returns True if the Pid of the record matches the value of "pid". * Otherwise false. */ -bool plugin_wakeup_match_pid(struct kshark_context *kshark_ctx, - struct kshark_entry *e, - int pid) +bool plugin_wakeup_match_rec_pid(struct kshark_context *kshark_ctx, + struct kshark_entry *e, + int pid) { struct plugin_sched_context *plugin_ctx; struct tep_record *record = NULL; @@ -182,7 +185,7 @@ bool plugin_wakeup_match_pid(struct kshark_context *kshark_ctx, record->data, &val); if (val) - wakeup_pid = plugin_get_wakeup_pid(record); + wakeup_pid = plugin_get_rec_wakeup_pid(record); } if (plugin_ctx->sched_wakeup_new_event && @@ -194,7 +197,7 @@ bool plugin_wakeup_match_pid(struct kshark_context *kshark_ctx, record->data, &val); if (val) - wakeup_pid = plugin_get_wakeup_new_pid(record); + wakeup_pid = plugin_get_rec_wakeup_new_pid(record); } free_record(record); @@ -212,14 +215,15 @@ bool plugin_wakeup_match_pid(struct kshark_context *kshark_ctx, * @param e: kshark_entry to be checked. * @param pid: Matching condition value. * - * @returns True if the Pid of the entry matches the value of "pid". + * @returns True if the Pid of the record matches the value of "pid". * Otherwise false. */ -bool plugin_switch_match_pid(struct kshark_context *kshark_ctx, - struct kshark_entry *e, - int pid) +bool plugin_switch_match_rec_pid(struct kshark_context *kshark_ctx, + struct kshark_entry *e, + int pid) { struct plugin_sched_context *plugin_ctx; + unsigned long long val; int switch_pid = -1; plugin_ctx = plugin_sched_context_handler; @@ -229,7 +233,12 @@ bool plugin_switch_match_pid(struct kshark_context *kshark_ctx, struct tep_record *record; record = kshark_read_at(kshark_ctx, e->offset); - switch_pid = tep_data_pid(plugin_ctx->pevent, record); + tep_read_number_field(plugin_ctx->sched_switch_prev_state_field, + record->data, &val); + + if (!(val & 0x7f)) + switch_pid = tep_data_pid(plugin_ctx->pevent, record); + free_record(record); } @@ -239,6 +248,32 @@ bool plugin_switch_match_pid(struct kshark_context *kshark_ctx, return false; } +/** + * @brief Process Id matching function adapted for sched_switch events. + * + * @param kshark_ctx: Input location for the session context pointer. + * @param e: kshark_entry to be checked. + * @param pid: Matching condition value. + * + * @returns True if the Pid of the entry matches the value of "pid". + * Otherwise false. + */ +bool plugin_switch_match_entry_pid(struct kshark_context *kshark_ctx, + struct kshark_entry *e, + int pid) +{ + struct plugin_sched_context *plugin_ctx; + + plugin_ctx = plugin_sched_context_handler; + + if (plugin_ctx->sched_switch_event && + e->event_id == plugin_ctx->sched_switch_event->id && + e->pid == pid) + return true; + + return false; +} + static void plugin_sched_action(struct kshark_context *kshark_ctx, struct tep_record *rec, struct kshark_entry *entry) diff --git a/kernel-shark-qt/src/plugins/sched_events.h b/kernel-shark-qt/src/plugins/sched_events.h index 481413f..28625e3 100644 --- a/kernel-shark-qt/src/plugins/sched_events.h +++ b/kernel-shark-qt/src/plugins/sched_events.h @@ -36,6 +36,9 @@ struct plugin_sched_context { /** Pointer to the sched_switch_comm_field format descriptor. */ struct tep_format_field *sched_switch_comm_field; + /** Pointer to the sched_switch_prev_state_field format descriptor. */ + struct tep_format_field *sched_switch_prev_state_field; + /** Pointer to the sched_wakeup_event object. */ struct tep_event_format *sched_wakeup_event; @@ -62,13 +65,15 @@ struct plugin_sched_context { int plugin_get_next_pid(struct tep_record *record); -int plugin_get_wakeup_pid(struct tep_record *record); +bool plugin_wakeup_match_rec_pid(struct kshark_context *kshark_ctx, + struct kshark_entry *e, int pid); -bool plugin_wakeup_match_pid(struct kshark_context *kshark_ctx, - struct kshark_entry *e, int pid); +bool plugin_switch_match_rec_pid(struct kshark_context *kshark_ctx, + struct kshark_entry *e, int pid); -bool plugin_switch_match_pid(struct kshark_context *kshark_ctx, - struct kshark_entry *e, int pid); +bool plugin_switch_match_entry_pid(struct kshark_context *kshark_ctx, + struct kshark_entry *e, + int pid); void plugin_draw(struct kshark_cpp_argv *argv, int pid, int draw_action); From patchwork Fri Nov 9 19:50:26 2018 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Yordan Karadzhov X-Patchwork-Id: 10759731 Return-Path: Received: from mail-cys01nam02on0088.outbound.protection.outlook.com ([104.47.37.88]:36407 "EHLO NAM02-CY1-obe.outbound.protection.outlook.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1725883AbeKJFdC (ORCPT ); Sat, 10 Nov 2018 00:33:02 -0500 From: Yordan Karadzhov To: "rostedt@goodmis.org" CC: "linux-trace-devel@vger.kernel.org" Subject: [PATCH v2 3/8] kernel-shark-qt: Update the visualization model when updating Graphs Date: Fri, 9 Nov 2018 19:50:26 +0000 Message-ID: <20181109195004.25455-4-ykaradzhov@vmware.com> References: <20181109195004.25455-1-ykaradzhov@vmware.com> In-Reply-To: <20181109195004.25455-1-ykaradzhov@vmware.com> Content-Language: en-US MIME-Version: 1.0 Sender: linux-trace-devel-owner@vger.kernel.org List-ID: Updating the model when the Graph widget is doing self-update, guarantees that all previously plotted graphs are wiped out before plotting something new. Signed-off-by: Yordan Karadzhov --- kernel-shark-qt/src/KsTraceGraph.cpp | 1 + 1 file changed, 1 insertion(+) diff --git a/kernel-shark-qt/src/KsTraceGraph.cpp b/kernel-shark-qt/src/KsTraceGraph.cpp index 21a09d0..29a5950 100644 --- a/kernel-shark-qt/src/KsTraceGraph.cpp +++ b/kernel-shark-qt/src/KsTraceGraph.cpp @@ -215,6 +215,7 @@ void KsTraceGraph::_selfUpdate() _updateGraphLegends(); _updateTimeLegends(); _markerReDraw(); + _glWindow.model()->update(); updateGeom(); } From patchwork Fri Nov 9 19:50:27 2018 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Yordan Karadzhov X-Patchwork-Id: 10759743 Return-Path: Received: from mail-cys01nam02on0088.outbound.protection.outlook.com ([104.47.37.88]:36407 "EHLO NAM02-CY1-obe.outbound.protection.outlook.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1725883AbeKJFdF (ORCPT ); Sat, 10 Nov 2018 00:33:05 -0500 From: Yordan Karadzhov To: "rostedt@goodmis.org" CC: "linux-trace-devel@vger.kernel.org" Subject: [PATCH v2 4/8] kernel-shark-qt: Add "Missed events" custom kshark_entry Date: Fri, 9 Nov 2018 19:50:27 +0000 Message-ID: <20181109195004.25455-5-ykaradzhov@vmware.com> References: <20181109195004.25455-1-ykaradzhov@vmware.com> In-Reply-To: <20181109195004.25455-1-ykaradzhov@vmware.com> Content-Language: en-US MIME-Version: 1.0 Sender: linux-trace-devel-owner@vger.kernel.org List-ID: Content-Length: 9780 The ring buffer used during the acquisition of the tracing data can overflow. In such a case a fraction of the data is lost. This patch introduces a custom kshark_entry used to indicate that some data has been overwrite (lost). Instruments for insertion and processing of "Missed events" entries are added. Signed-off-by: Yordan Karadzhov --- kernel-shark-qt/src/libkshark.c | 196 ++++++++++++++++++++++++++------ kernel-shark-qt/src/libkshark.h | 16 +++ 2 files changed, 179 insertions(+), 33 deletions(-) diff --git a/kernel-shark-qt/src/libkshark.c b/kernel-shark-qt/src/libkshark.c index 64236a5..1a39968 100644 --- a/kernel-shark-qt/src/libkshark.c +++ b/kernel-shark-qt/src/libkshark.c @@ -16,7 +16,6 @@ #include #include #include -#include // KernelShark #include "libkshark.h" @@ -558,6 +557,52 @@ static void kshark_set_entry_values(struct kshark_context *kshark_ctx, entry->pid = tep_data_pid(kshark_ctx->pevent, record); } +/** Prior time offset of the "missed_events" entry. */ +#define ME_ENTRY_TIME_SHIFT 10 + +static void missed_events_action(struct kshark_context *kshark_ctx, + struct tep_record *record, + struct kshark_entry *entry) +{ + /* + * Use the offset field of the entry to store the number of missed + * events. + */ + entry->offset = record->missed_events; + + entry->cpu = record->cpu; + + /* + * Position the "missed_events" entry a bit before (in time) + * the original record. + */ + entry->ts = record->ts - ME_ENTRY_TIME_SHIFT; + + /* All custom entries must have negative event Identifiers. */ + entry->event_id = KS_EVENT_OVERFLOW; + + entry->visible = 0xFF; + + entry->pid = tep_data_pid(kshark_ctx->pevent, record); +} + +static const char* missed_events_dump(struct kshark_context *kshark_ctx, + const struct kshark_entry *entry, + bool get_info) +{ + int size = 0; + static char *buffer; + + if (get_info) + size = asprintf(&buffer, "missed_events=%i", (int) entry->offset); + else + size = asprintf(&buffer, "missed_events"); + if (size > 0) + return buffer; + + return NULL; +} + /** * rec_list is used to pass the data to the load functions. * The rec_list will contain the list of entries from the source, @@ -649,6 +694,21 @@ static size_t get_records(struct kshark_context *kshark_ctx, struct kshark_entry *entry; int ret; + if (rec->missed_events) { + /* + * Insert a custom "missed_events" entry just + * befor this record. + */ + entry = &temp_rec->entry; + missed_events_action(kshark_ctx, rec, entry); + + temp_next = &temp_rec->next; + ++count; + + /* Now allocate a new rec_list node and comtinue. */ + *temp_next = temp_rec = calloc(1, sizeof(*temp_rec)); + } + entry = &temp_rec->entry; kshark_set_entry_values(kshark_ctx, rec, entry); @@ -1006,6 +1066,9 @@ const char *kshark_get_latency_easy(struct kshark_entry *entry) if (!kshark_instance(&kshark_ctx)) return NULL; + if (entry->event_id < 0) + return NULL; + data = kshark_read_at(kshark_ctx, entry->offset); lat = kshark_get_latency(kshark_ctx->pevent, data); free_record(data); @@ -1048,7 +1111,7 @@ int kshark_get_event_id_easy(struct kshark_entry *entry) free_record(data); } - return event_id; + return (event_id == -1)? EFAULT : event_id; } /** @@ -1070,11 +1133,20 @@ const char *kshark_get_event_name_easy(struct kshark_entry *entry) struct tep_event_format *event; int event_id = kshark_get_event_id_easy(entry); - - if (event_id < 0) + if (event_id == EFAULT) return NULL; kshark_instance(&kshark_ctx); + + if (event_id < 0) { + switch (event_id) { + case KS_EVENT_OVERFLOW: + return missed_events_dump(kshark_ctx, entry, false); + default: + return NULL; + } + } + event = tep_data_event_from_type(kshark_ctx->pevent, event_id); if (event) return event->name; @@ -1105,6 +1177,15 @@ const char *kshark_get_info_easy(struct kshark_entry *entry) if (!kshark_instance(&kshark_ctx)) return NULL; + if (entry->event_id < 0) { + switch (entry->event_id) { + case KS_EVENT_OVERFLOW: + return missed_events_dump(kshark_ctx, entry, true); + default: + return NULL; + } + } + data = kshark_read_at(kshark_ctx, entry->offset); event_id = tep_data_type(kshark_ctx->pevent, data); @@ -1133,6 +1214,43 @@ void kshark_convert_nano(uint64_t time, uint64_t *sec, uint64_t *usec) *usec = (time - s * 1000000000ULL) / 1000; } +/** + * @brief Dump into a string the content a custom entry. The function allocates + * a null terminated string and returns a pointer to this string. + * + * @param kshark_ctx: Input location for the session context pointer. + * @param entry: A Kernel Shark entry to be printed. + * @param info_func: + * + * @returns The returned string contains a semicolon-separated list of data + * fields. The user has to free the returned string. + */ +char* kshark_dump_custom_entry(struct kshark_context *kshark_ctx, + const struct kshark_entry *entry, + kshark_custom_info_func info_func) +{ + const char *event_name, *task, *info; + char *entry_str; + int size = 0; + + task = tep_data_comm_from_pid(kshark_ctx->pevent, entry->pid); + event_name = info_func(kshark_ctx, entry, false); + info = info_func(kshark_ctx, entry, true); + + size = asprintf(&entry_str, "%li; %s-%i; CPU %i; ; %s; %s", + entry->ts, + task, + entry->pid, + entry->cpu, + event_name, + info); + + if (size > 0) + return entry_str; + + return NULL; +} + /** * @brief Dump into a string the content of one entry. The function allocates * a null terminated string and returns a pointer to this string. The @@ -1147,48 +1265,60 @@ char* kshark_dump_entry(const struct kshark_entry *entry) { const char *event_name, *task, *lat, *info; struct kshark_context *kshark_ctx; - struct tep_record *data; - struct tep_event_format *event; char *temp_str, *entry_str; - int event_id, size = 0; + int size = 0; kshark_ctx = NULL; if (!kshark_instance(&kshark_ctx) || !init_thread_seq()) return NULL; - data = kshark_read_at(kshark_ctx, entry->offset); + task = tep_data_comm_from_pid(kshark_ctx->pevent, entry->pid); - event_id = tep_data_type(kshark_ctx->pevent, data); - event = tep_data_event_from_type(kshark_ctx->pevent, event_id); + if (entry->event_id >= 0) { + struct tep_event_format *event; + struct tep_record *data; - event_name = event? event->name : "[UNKNOWN EVENT]"; - task = tep_data_comm_from_pid(kshark_ctx->pevent, entry->pid); - lat = kshark_get_latency(kshark_ctx->pevent, data); + data = kshark_read_at(kshark_ctx, entry->offset); - size = asprintf(&temp_str, "%li %s-%i; CPU %i; %s;", - entry->ts, - task, - entry->pid, - entry->cpu, - lat); + event = tep_data_event_from_type(kshark_ctx->pevent, + entry->event_id); - info = kshark_get_info(kshark_ctx->pevent, data, event); - if (size > 0) { - size = asprintf(&entry_str, "%s %s; %s; 0x%x", - temp_str, - event_name, - info, - entry->visible); + event_name = event? event->name : "[UNKNOWN EVENT]"; + lat = kshark_get_latency(kshark_ctx->pevent, data); - free(temp_str); - } + size = asprintf(&temp_str, "%li; %s-%i; CPU %i; %s;", + entry->ts, + task, + entry->pid, + entry->cpu, + lat); - free_record(data); + info = kshark_get_info(kshark_ctx->pevent, data, event); - if (size > 0) - return entry_str; + if (size > 0) { + size = asprintf(&entry_str, "%s %s; %s; 0x%x", + temp_str, + event_name, + info, + entry->visible); - return NULL; + free(temp_str); + } + + free_record(data); + if (size < 1) + entry_str = NULL; + } else { + switch (entry->event_id) { + case KS_EVENT_OVERFLOW: + entry_str = kshark_dump_custom_entry(kshark_ctx, entry, + missed_events_dump); + default: + entry_str = NULL; + } + } + + return entry_str; } /** @@ -1402,7 +1532,7 @@ get_entry(const struct kshark_entry_request *req, if (index) { if (e) - *index = (e->event_id >= 0)? i : KS_FILTERED_BIN; + *index = (e->cpu != KS_FILTERED_BIN)? i : KS_FILTERED_BIN; else *index = KS_EMPTY_BIN; } diff --git a/kernel-shark-qt/src/libkshark.h b/kernel-shark-qt/src/libkshark.h index 2b39c26..b94bdc3 100644 --- a/kernel-shark-qt/src/libkshark.h +++ b/kernel-shark-qt/src/libkshark.h @@ -15,6 +15,7 @@ // C #include #include +#include // Json-C #include @@ -164,6 +165,18 @@ void kshark_convert_nano(uint64_t time, uint64_t *sec, uint64_t *usec); char* kshark_dump_entry(const struct kshark_entry *entry); +/** + * Custom entry info function type. To be user for dumping info for custom + * KernelShark entryes. + */ +typedef const char *(kshark_custom_info_func)(struct kshark_context *, + const struct kshark_entry *, + bool); + +char* kshark_dump_custom_entry(struct kshark_context *kshark_ctx, + const struct kshark_entry *entry, + kshark_custom_info_func info_func); + struct tep_record *kshark_read_at(struct kshark_context *kshark_ctx, uint64_t offset); @@ -281,6 +294,9 @@ bool kshark_match_cpu(struct kshark_context *kshark_ctx, /** Filtered bin identifier. */ #define KS_FILTERED_BIN -2 +/** Overflow Event identifier. */ +#define KS_EVENT_OVERFLOW (-EOVERFLOW) + /** Matching condition function type. To be user for data requests */ typedef bool (matching_condition_func)(struct kshark_context*, struct kshark_entry*, From patchwork Fri Nov 9 19:50:28 2018 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Yordan Karadzhov X-Patchwork-Id: 10759733 Return-Path: Received: from mail-cys01nam02on0088.outbound.protection.outlook.com ([104.47.37.88]:36407 "EHLO NAM02-CY1-obe.outbound.protection.outlook.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1725872AbeKJFdE (ORCPT ); Sat, 10 Nov 2018 00:33:04 -0500 From: Yordan Karadzhov To: "rostedt@goodmis.org" CC: "linux-trace-devel@vger.kernel.org" Subject: [PATCH v2 5/8] kernel-shark-qt: Add instrumentation for "Missed events" to the model Date: Fri, 9 Nov 2018 19:50:28 +0000 Message-ID: <20181109195004.25455-6-ykaradzhov@vmware.com> References: <20181109195004.25455-1-ykaradzhov@vmware.com> In-Reply-To: <20181109195004.25455-1-ykaradzhov@vmware.com> Content-Language: en-US MIME-Version: 1.0 Sender: linux-trace-devel-owner@vger.kernel.org List-ID: Content-Length: 3609 This patch adds to the Visualization model instruments, used for finding and plotting "Missed events". Signed-off-by: Yordan Karadzhov --- kernel-shark-qt/src/libkshark-model.c | 60 +++++++++++++++++++++++++++ kernel-shark-qt/src/libkshark-model.h | 12 ++++++ 2 files changed, 72 insertions(+) diff --git a/kernel-shark-qt/src/libkshark-model.c b/kernel-shark-qt/src/libkshark-model.c index 7800090..ef6ad48 100644 --- a/kernel-shark-qt/src/libkshark-model.c +++ b/kernel-shark-qt/src/libkshark-model.c @@ -1222,3 +1222,63 @@ bool ksmodel_task_visible_event_exist(struct kshark_trace_histo *histo, return true; } + +static bool match_cpu_missed_events(struct kshark_context *kshark_ctx, + struct kshark_entry *e, int cpu) +{ + return e->event_id == -EOVERFLOW && e->cpu == cpu; +} + +static bool match_pid_missed_events(struct kshark_context *kshark_ctx, + struct kshark_entry *e, int pid) +{ + return e->event_id == -EOVERFLOW && e->pid == pid; +} + +/** + * @brief In a given CPU and bin, start from the front end of the bin and go towards + * the back end, searching for a Missed Events entry. + * + * @param histo: Input location for the model descriptor. + * @param bin: Bin id. + * @param cpu: CPU Id. + * @param col: Optional input location for Data collection. + * @param index: Optional output location for the index of the requested + * entry inside the array. + * + * @returns Pointer ot a kshark_entry, if an entry has been found. Else NULL. + */ +const struct kshark_entry * +ksmodel_get_cpu_missed_events(struct kshark_trace_histo *histo, + int bin, int cpu, + struct kshark_entry_collection *col, + ssize_t *index) +{ + return ksmodel_get_entry_front(histo, bin, true, + match_cpu_missed_events, cpu, + col, index); +} + +/** + * @brief In a given task and bin, start from the front end of the bin and go towards + * the back end, searching for a Missed Events entry. + * + * @param histo: Input location for the model descriptor. + * @param bin: Bin id. + * @param pid: Process Id of the task. + * @param col: Optional input location for Data collection. + * @param index: Optional output location for the index of the requested + * entry inside the array. + * + * @returns Pointer ot a kshark_entry, if an entry has been found. Else NULL. + */ +const struct kshark_entry * +ksmodel_get_task_missed_events(struct kshark_trace_histo *histo, + int bin, int pid, + struct kshark_entry_collection *col, + ssize_t *index) +{ + return ksmodel_get_entry_front(histo, bin, true, + match_pid_missed_events, pid, + col, index); +} diff --git a/kernel-shark-qt/src/libkshark-model.h b/kernel-shark-qt/src/libkshark-model.h index 1cf68da..db681cc 100644 --- a/kernel-shark-qt/src/libkshark-model.h +++ b/kernel-shark-qt/src/libkshark-model.h @@ -148,6 +148,18 @@ bool ksmodel_task_visible_event_exist(struct kshark_trace_histo *histo, struct kshark_entry_collection *col, ssize_t *index); +const struct kshark_entry * +ksmodel_get_cpu_missed_events(struct kshark_trace_histo *histo, + int bin, int cpu, + struct kshark_entry_collection *col, + ssize_t *index); + +const struct kshark_entry * +ksmodel_get_task_missed_events(struct kshark_trace_histo *histo, + int bin, int pid, + struct kshark_entry_collection *col, + ssize_t *index); + static inline double ksmodel_bin_time(struct kshark_trace_histo *histo, int bin) { From patchwork Fri Nov 9 19:50:29 2018 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Yordan Karadzhov X-Patchwork-Id: 10759741 Return-Path: Received: from mail-cys01nam02on0088.outbound.protection.outlook.com ([104.47.37.88]:36407 "EHLO NAM02-CY1-obe.outbound.protection.outlook.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1725883AbeKJFdV (ORCPT ); Sat, 10 Nov 2018 00:33:21 -0500 From: Yordan Karadzhov To: "rostedt@goodmis.org" CC: "linux-trace-devel@vger.kernel.org" Subject: [PATCH v2 6/8] kernel-shark-qt: Add tot_count field to the model descriptor Date: Fri, 9 Nov 2018 19:50:29 +0000 Message-ID: <20181109195004.25455-7-ykaradzhov@vmware.com> References: <20181109195004.25455-1-ykaradzhov@vmware.com> In-Reply-To: <20181109195004.25455-1-ykaradzhov@vmware.com> Content-Language: en-US MIME-Version: 1.0 Sender: linux-trace-devel-owner@vger.kernel.org List-ID: Content-Length: 2081 The tot_count field of the Visualization model descriptor provides fast access to the total number of entries being currently visualized. The total count can be useful in various cases. For example the sched event plugin can use it for knowing when to plot wakeup latency. Signed-off-by: Yordan Karadzhov --- kernel-shark-qt/src/libkshark-model.c | 7 +++++++ kernel-shark-qt/src/libkshark-model.h | 3 +++ 2 files changed, 10 insertions(+) diff --git a/kernel-shark-qt/src/libkshark-model.c b/kernel-shark-qt/src/libkshark-model.c index ef6ad48..461f88e 100644 --- a/kernel-shark-qt/src/libkshark-model.c +++ b/kernel-shark-qt/src/libkshark-model.c @@ -298,6 +298,7 @@ static void ksmodel_set_bin_counts(struct kshark_trace_histo *histo) { int i = 0, prev_not_empty; + histo->tot_count = 0; memset(&histo->bin_count[0], 0, (histo->n_bins) * sizeof(histo->bin_count[0])); /* @@ -329,6 +330,10 @@ static void ksmodel_set_bin_counts(struct kshark_trace_histo *histo) histo->bin_count[prev_not_empty] = histo->map[i] - histo->map[prev_not_empty]; + if (prev_not_empty != LOB(histo)) + histo->tot_count += + histo->bin_count[prev_not_empty]; + prev_not_empty = i; } } @@ -350,6 +355,8 @@ static void ksmodel_set_bin_counts(struct kshark_trace_histo *histo) histo->bin_count[prev_not_empty] = histo->map[UOB(histo)] - histo->map[prev_not_empty]; } + + histo->tot_count += histo->bin_count[prev_not_empty]; } /** diff --git a/kernel-shark-qt/src/libkshark-model.h b/kernel-shark-qt/src/libkshark-model.h index db681cc..95c30b6 100644 --- a/kernel-shark-qt/src/libkshark-model.h +++ b/kernel-shark-qt/src/libkshark-model.h @@ -51,6 +51,9 @@ struct kshark_trace_histo { /** Number of entries in each bin. */ size_t *bin_count; + /** Total number of entries in all bin except the overflow bins. */ + int tot_count; + /** * Lower edge of the time-window to be visualized. Only entries having * timestamp >= min will be visualized. From patchwork Fri Nov 9 19:50:30 2018 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Yordan Karadzhov X-Patchwork-Id: 10759739 Return-Path: Received: from mail-cys01nam02on0082.outbound.protection.outlook.com ([104.47.37.82]:58643 "EHLO NAM02-CY1-obe.outbound.protection.outlook.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1725872AbeKJFdO (ORCPT ); Sat, 10 Nov 2018 00:33:14 -0500 From: Yordan Karadzhov To: "rostedt@goodmis.org" CC: "linux-trace-devel@vger.kernel.org" Subject: [PATCH v2 7/8] kernel-shark-qt: Add "Missed events" plugin for KernelShark Date: Fri, 9 Nov 2018 19:50:30 +0000 Message-ID: <20181109195004.25455-8-ykaradzhov@vmware.com> References: <20181109195004.25455-1-ykaradzhov@vmware.com> In-Reply-To: <20181109195004.25455-1-ykaradzhov@vmware.com> Content-Language: en-US MIME-Version: 1.0 Sender: linux-trace-devel-owner@vger.kernel.org List-ID: Content-Length: 7502 The "Missed events" plugin displays a special marker that indicates the position (in time) of the missed (overwritten) data. Signed-off-by: Yordan Karadzhov --- kernel-shark-qt/src/plugins/CMakeLists.txt | 6 +- kernel-shark-qt/src/plugins/MissedEvents.cpp | 149 +++++++++++++++++++ kernel-shark-qt/src/plugins/missed_events.c | 41 +++++ kernel-shark-qt/src/plugins/missed_events.h | 30 ++++ 4 files changed, 225 insertions(+), 1 deletion(-) create mode 100644 kernel-shark-qt/src/plugins/MissedEvents.cpp create mode 100644 kernel-shark-qt/src/plugins/missed_events.c create mode 100644 kernel-shark-qt/src/plugins/missed_events.h diff --git a/kernel-shark-qt/src/plugins/CMakeLists.txt b/kernel-shark-qt/src/plugins/CMakeLists.txt index 2d7251d..853214e 100644 --- a/kernel-shark-qt/src/plugins/CMakeLists.txt +++ b/kernel-shark-qt/src/plugins/CMakeLists.txt @@ -24,7 +24,11 @@ BUILD_PLUGIN(NAME sched_events list(APPEND PLUGIN_LIST "sched_events default") # This plugin will be loaded by default # list(APPEND PLUGIN_LIST "sched_events") # This plugin isn't loaded by default -install(TARGETS sched_events +BUILD_PLUGIN(NAME missed_events + SOURCE missed_events.c MissedEvents.cpp) +list(APPEND PLUGIN_LIST "missed_events default") # This plugin will be loaded by default + +install(TARGETS sched_events missed_events LIBRARY DESTINATION /usr/local/lib/kshark/) set(PLUGINS ${PLUGIN_LIST} PARENT_SCOPE) diff --git a/kernel-shark-qt/src/plugins/MissedEvents.cpp b/kernel-shark-qt/src/plugins/MissedEvents.cpp new file mode 100644 index 0000000..05dfcb5 --- /dev/null +++ b/kernel-shark-qt/src/plugins/MissedEvents.cpp @@ -0,0 +1,149 @@ +// SPDX-License-Identifier: LGPL-2.1 + +/* + * Copyright (C) 2018 VMware Inc, Yordan Karadzhov + */ + +/** + * @file MissedEvents.cpp + * @brief Plugin for visualization of events, missed due to overflow of the ring buffer. + */ + +// C++ +#include + +// KernelShark +#include "libkshark.h" +#include "plugins/missed_events.h" +#include "KsPlotTools.hpp" +#include "KsPlugins.hpp" + +using namespace KsPlot; + +/** + * This class represents the graphical element of the KernelShark marker for + * Missed events. + */ +class MissedEventsMark : public PlotObject { +public: + /** Create a default Missed events marker. */ + MissedEventsMark() : _base(0, 0), _height(0) + { + _color = {0, 0, 255}; + _size = 2; + } + + /** + * @brief Create and position a Missed events marker. + * + * @param p: Base point of the marker. + * @param h: vertical size (height) of the marker. + */ + MissedEventsMark(const Point &p, int h) + : _base(p.x(), p.y()), _height(h) + { + _color = {0, 0, 255}; + _size = 2; + } + + /** Set the Base point of the marker. */ + void setBase(const Point &p) {_base.set(p.x(), p.y());} + + /** Set the vertical size (height) point of the marker. */ + void setHeight(int h) {_height = h;} + +private: + /** Base point of the Mark's line. */ + Point _base; + + /** The vertical size (height) of the Mark. */ + int _height; + + void _draw(const Color &col, float size = 1.) const override; +}; + +void MissedEventsMark::_draw(const Color &col, float size) const +{ + Point p(_base.x(), _base.y() - _height); + drawLine(_base, p, col, size); + + Rectangle rec; + rec.setPoint(0, p.x(), p.y()); + rec.setPoint(1, p.x() - _height / 4, p.y()); + rec.setPoint(2, p.x() - _height / 4, p.y() + _height / 4); + rec.setPoint(3, p.x(), p.y() + _height / 4); + rec._color = col; + rec.draw(); +} + +//! @cond Doxygen_Suppress + +#define PLUGIN_MAX_ENTRIES 10000 + +#define KS_TASK_COLLECTION_MARGIN 25 + +//! @endcond + +static void pluginDraw(kshark_context *kshark_ctx, + KsCppArgV *argvCpp, + int val, int draw_action) +{ + int height = argvCpp->_graph->getHeight(); + const kshark_entry *entry(nullptr); + MissedEventsMark *mark; + ssize_t index; + + int nBins = argvCpp->_graph->size(); + for (int bin = 0; bin < nBins; ++bin) { + if (draw_action == KSHARK_PLUGIN_TASK_DRAW) + entry = ksmodel_get_task_missed_events(argvCpp->_histo, + bin, val, + nullptr, + &index); + if (draw_action == KSHARK_PLUGIN_CPU_DRAW) + entry = ksmodel_get_cpu_missed_events(argvCpp->_histo, + bin, val, + nullptr, + &index); + + if (entry) { + mark = new MissedEventsMark(argvCpp->_graph->getBin(bin)._base, + height); + + argvCpp->_shapes->push_front(mark); + } + } +} + +/** + * @brief Plugin's draw function. + * + * @param argv_c: A C pointer to be converted to KsCppArgV (C++ struct). + * @param val: Process or CPU Id value. + * @param draw_action: Draw action identifier. + */ +void draw_missed_events(kshark_cpp_argv *argv_c, + int val, int draw_action) +{ + kshark_context *kshark_ctx(NULL); + + if (!kshark_instance(&kshark_ctx)) + return; + + KsCppArgV *argvCpp = KS_ARGV_TO_CPP(argv_c); + + /* + * Plotting the "Missed events" makes sense only in the case of a deep + * zoom. Here we set a threshold based on the total number of entries + * being visualized by the model. + * Don't be afraid to play with different values for this threshold. + */ + if (argvCpp->_histo->tot_count > PLUGIN_MAX_ENTRIES) + return; + + try { + pluginDraw(kshark_ctx, argvCpp, val, draw_action); + } catch (const std::exception &exc) { + std::cerr << "Exception in MissedEvents\n" << exc.what(); + } +} diff --git a/kernel-shark-qt/src/plugins/missed_events.c b/kernel-shark-qt/src/plugins/missed_events.c new file mode 100644 index 0000000..cf652bf --- /dev/null +++ b/kernel-shark-qt/src/plugins/missed_events.c @@ -0,0 +1,41 @@ +// SPDX-License-Identifier: LGPL-2.1 + +/* + * Copyright (C) 2018 VMware Inc, Yordan Karadzhov + */ + +/** + * @file missed_events.c + * @brief Plugin for visualization of missed events due to overflow of the + * ring buffer. + */ + +// KernelShark +#include "plugins/missed_events.h" + +static void nop_action(struct kshark_context *kshark_ctx, + struct tep_record *record, + struct kshark_entry *entry) +{} + +/** Load this plugin. */ +int KSHARK_PLUGIN_INITIALIZER(struct kshark_context *kshark_ctx) +{ + kshark_register_event_handler(&kshark_ctx->event_handlers, + KS_EVENT_OVERFLOW, + nop_action, + draw_missed_events); + + return 1; +} + +/** Unload this plugin. */ +int KSHARK_PLUGIN_DEINITIALIZER(struct kshark_context *kshark_ctx) +{ + kshark_unregister_event_handler(&kshark_ctx->event_handlers, + KS_EVENT_OVERFLOW, + nop_action, + draw_missed_events); + + return 1; +} diff --git a/kernel-shark-qt/src/plugins/missed_events.h b/kernel-shark-qt/src/plugins/missed_events.h new file mode 100644 index 0000000..e05d79a --- /dev/null +++ b/kernel-shark-qt/src/plugins/missed_events.h @@ -0,0 +1,30 @@ +/* SPDX-License-Identifier: LGPL-2.1 */ + +/* + * Copyright (C) 2018 VMware Inc, Yordan Karadzhov + */ + +/** + * @file missed_events.h + * @brief Plugin for visualization of missed events due to overflow of the + * ring buffer. + */ + +#ifndef _KS_PLUGIN_M_EVTS_H +#define _KS_PLUGIN_M_EVTS_H + +// KernelShark +#include "libkshark.h" + +#ifdef __cplusplus +extern "C" { +#endif + +void draw_missed_events(struct kshark_cpp_argv *argv, + int pid, int draw_action); + +#ifdef __cplusplus +} +#endif + +#endif From patchwork Fri Nov 9 19:50:31 2018 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Yordan Karadzhov X-Patchwork-Id: 10759735 Return-Path: Received: from mail-cys01nam02on0088.outbound.protection.outlook.com ([104.47.37.88]:36407 "EHLO NAM02-CY1-obe.outbound.protection.outlook.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1725872AbeKJFdH (ORCPT ); Sat, 10 Nov 2018 00:33:07 -0500 From: Yordan Karadzhov To: "rostedt@goodmis.org" CC: "linux-trace-devel@vger.kernel.org" Subject: [PATCH v2 8/8] kernel-shark-qt: Update Sched Events plugin Date: Fri, 9 Nov 2018 19:50:31 +0000 Message-ID: <20181109195004.25455-9-ykaradzhov@vmware.com> References: <20181109195004.25455-1-ykaradzhov@vmware.com> In-Reply-To: <20181109195004.25455-1-ykaradzhov@vmware.com> Content-Language: en-US MIME-Version: 1.0 Sender: linux-trace-devel-owner@vger.kernel.org List-ID: Content-Length: 3808 This patch updates the Sched Events plugin to use the recently introduced "Missed events" entries and tot_count field of the Visualization model descriptor in its plotting logic. We need this update because the sched plugin would get confused because of missed events, where we could have missed events hiding wakeups, and only have the sched switch, or a wakeup with a missing sched switch would break the plotting of the latency. Signed-off-by: Yordan Karadzhov --- kernel-shark-qt/src/plugins/SchedEvents.cpp | 43 ++++++++++----------- 1 file changed, 20 insertions(+), 23 deletions(-) diff --git a/kernel-shark-qt/src/plugins/SchedEvents.cpp b/kernel-shark-qt/src/plugins/SchedEvents.cpp index eec60fe..b4596c9 100644 --- a/kernel-shark-qt/src/plugins/SchedEvents.cpp +++ b/kernel-shark-qt/src/plugins/SchedEvents.cpp @@ -28,7 +28,7 @@ #define PLUGIN_MIN_BOX_SIZE 4 -#define PLUGIN_MAX_ENTRIES_PER_BIN 500 +#define PLUGIN_MAX_ENTRIES 10000 #define KS_TASK_COLLECTION_MARGIN 25 @@ -54,11 +54,11 @@ static void pluginDraw(plugin_sched_context *plugin_ctx, KsPlot::Graph *graph, KsPlot::PlotObjList *shapes) { - const kshark_entry *entryClose, *entryOpen; + const kshark_entry *entryClose, *entryOpen, *entryME; + ssize_t indexClose(0), indexOpen(0), indexME(0); std::function ifSchedBack; KsPlot::Rectangle *rec = nullptr; int height = graph->getHeight() * .3; - ssize_t indexClose(0), indexOpen(0); auto openBox = [&] (const KsPlot::Point &p) { @@ -104,24 +104,6 @@ static void pluginDraw(plugin_sched_context *plugin_ctx, }; for (int bin = 0; bin < graph->size(); ++bin) { - /** - * Plotting the latencies makes sense only in the case of a - * deep zoom. Here we set a naive threshold based on the number - * of entries inside the current bin. This cut seems to work - * well in all cases I tested so far, but it may result in - * unexpected behavior with some unusual trace data-sets. - * TODO: find a better criteria for deciding when to start - * plotting latencies. - */ - if (ksmodel_bin_count(histo, bin) > PLUGIN_MAX_ENTRIES_PER_BIN) { - if (rec) { - delete rec; - rec = nullptr; - } - - continue; - } - /* * Starting from the first element in this bin, go forward * in time until you find a trace entry that satisfies the @@ -131,6 +113,11 @@ static void pluginDraw(plugin_sched_context *plugin_ctx, plugin_switch_match_entry_pid, pid, col, &indexClose); + entryME = ksmodel_get_task_missed_events(histo, + bin, pid, + col, + &indexME); + if (e == SchedEvent::Switch) { /* * Starting from the last element in this bin, go backward @@ -155,10 +142,12 @@ static void pluginDraw(plugin_sched_context *plugin_ctx, } if (rec) { - if (entryClose) { + if (entryME || entryClose) { /* Close the box in this bin. */ closeBox(graph->getBin(bin)._base); - if (entryOpen && indexClose < indexOpen) { + if (entryOpen && + indexME < indexOpen && + indexClose < indexOpen) { /* * We have a Sched switch entry that * comes after (in time) the closure of @@ -288,6 +277,14 @@ void plugin_draw(kshark_cpp_argv *argv_c, int pid, int draw_action) tracecmd_filter_id_add(plugin_ctx->second_pass_hash, pid); } + /* + * Plotting the latencies makes sense only in the case of a deep zoom. + * Here we set a threshold based on the total number of entries being + * visualized by the model. + * Don't be afraid to play with different values for this threshold. + */ + if (argvCpp->_histo->tot_count > PLUGIN_MAX_ENTRIES) + return; try { pluginDraw(plugin_ctx, kshark_ctx, argvCpp->_histo, col,