コグノスケ

KernelSharkのLatency列

目次: Linux

KernelSharkのイベント情報を見ると「Latency」なる列があって「d..2.」のような謎の表示がなされています。これは一体何なんでしょうか？

KernelSharkのドキュメント（The List View - KernelShark）を見ると、

Latency - The latency is broken into 4 fields:

    Interrupts disabled - 'd' if interrupts are disabled, otherwise '.'
    Need reschedule - 'N' if the kernel was notified that a schedule is needed, otherwise '.'
    In IRQ - 'h' if in a hard IRQ (hardware triggered), 's' if in a soft IRQ (context where the kernel initiated a the IRQ handler) or if soft IRQs are disabled, 'H' if in a hard IRQ and soft IRQs are disabled or the hard IRQ triggered while processing a soft IRQ, otherwise '.'
    Preemption counter - The index of the preemption counter. If it is other than zero, then the kernel will not preempt the running tasks, even if a schedule has been requested by some event. If the counter is zero, then '.' is shown. 

だそうです。なるほど4桁分の意味は分かりました。でも5桁目はどういう意味でしょう？昨日構築したKernelSharkのデバッグ環境を使って調べましょう。

どこで表示しているのか？

まずLatencyの表示をどこで作っているのかが全く分からなくて困りました。Qtアプリ全般に言えますが、コールバックが多すぎてまともに追えないです。さらにKernelSharkは独自のModel/Viewアーキテクチャみたいなものまであり地獄の様相です。

まともにコードを読むのは早々に諦めて適当にgrepしたりprintfを追加して、下記の関数がLatencyの文字列を作っているらしいことを突き止めました。

// kernel-shark/src/libkshark-tepdata.c

static char *tepdata_get_latency(struct kshark_data_stream *stream,
				 const struct kshark_entry *entry)
{
	struct tep_record *record;
	char *buffer;

	/* Check if this is a "Missed event" (event_id < 0). */
	if (!init_thread_seq() || entry->event_id < 0)
		return NULL;

	/*
	 * Currently the data reading operations are not thread-safe.
	 * Use a mutex to protect the access.
	 */
	pthread_mutex_lock(&stream->input_mutex);

	record = tracecmd_read_at(kshark_get_tep_input(stream), entry->offset, NULL);

	if (!record) {
		pthread_mutex_unlock(&stream->input_mutex);
		return NULL;
	}

	trace_seq_reset(&seq);
	//★★★★この関数呼び出しで「d..2.」のような文字列を生成している
	tep_print_event(kshark_get_tep(stream), &seq, record,
			"%s", TEP_PRINT_LATENCY);

	tracecmd_free_record(record);

	pthread_mutex_unlock(&stream->input_mutex);

	if (asprintf(&buffer, "%s", seq.buffer)  <= 0)
		return NULL;

	return buffer;
}

#0  tepdata_get_latency (stream=0x7fff30000bd0, entry=0x7fff31aec460) at .../kernel-shark/src/libkshark-tepdata.c:35
#1  0x00007ffff7f4fa68 in KsViewModel::getValueStr (this=0x7fffffffc318, column=<optimized out>, row=0) at .../kernel-shark/src/KsModels.cpp:358
#2  0x00007ffff7f4fad1 in KsViewModel::getValue (this=<optimized out>, column=<optimized out>, row=<optimized out>) at .../kernel-shark/src/KsModels.cpp:377
#3  0x00007ffff7f4fb33 in KsViewModel::data (this=<optimized out>, index=<optimized out>, role=<optimized out>) at .../kernel-shark/src/KsModels.cpp:312
#4  0x00007ffff6788e2e in QSortFilterProxyModel::data(QModelIndex const&, int) const () at /lib/x86_64-linux-gnu/libQt6Core.so.6
#5  0x00007ffff7aa9e96 in QItemDelegate::paint(QPainter*, QStyleOptionViewItem const&, QModelIndex const&) const () at /lib/x86_64-linux-gnu/libQt6Widgets.so.6
#6  0x00007ffff7ada750 in ??? () at /lib/x86_64-linux-gnu/libQt6Widgets.so.6
#7  0x00007ffff7adf581 in QTableView::paintEvent(QPaintEvent*) () at /lib/x86_64-linux-gnu/libQt6Widgets.so.6
#8  0x00007ffff78040c5 in QWidget::event(QEvent*) () at /lib/x86_64-linux-gnu/libQt6Widgets.so.6
#9  0x00007ffff789c3e6 in QFrame::event(QEvent*) () at /lib/x86_64-linux-gnu/libQt6Widgets.so.6
#10 0x00007ffff6595eda in QCoreApplicationPrivate::sendThroughObjectEventFilters(QObject*, QEvent*) () at /lib/x86_64-linux-gnu/libQt6Core.so.6
#11 0x00007ffff77b47d5 in QApplicationPrivate::notify_helper(QObject*, QEvent*) () at /lib/x86_64-linux-gnu/libQt6Widgets.so.6
#12 0x00007ffff6596630 in QCoreApplication::notifyInternal2(QObject*, QEvent*) () at /lib/x86_64-linux-gnu/libQt6Core.so.6
#13 0x00007ffff77f3693 in QWidgetPrivate::sendPaintEvent(QRegion const&) () at /lib/x86_64-linux-gnu/libQt6Widgets.so.6
#14 0x00007ffff77f55a3 in QWidgetPrivate::drawWidget(QPaintDevice*, QRegion const&, QPoint const&, QFlags<QWidgetPrivate::DrawWidgetFlag>, QPainter*, QWidgetRepaintManager*) () at /lib/x86_64-linux-gnu/libQt6Widgets.so.6
#15 0x00007ffff7817501 in QWidgetRepaintManager::paintAndFlush() () at /lib/x86_64-linux-gnu/libQt6Widgets.so.6
#16 0x00007ffff7803afd in QWidget::event(QEvent*) () at /lib/x86_64-linux-gnu/libQt6Widgets.so.6
#17 0x00007ffff77b47e5 in QApplicationPrivate::notify_helper(QObject*, QEvent*) () at /lib/x86_64-linux-gnu/libQt6Widgets.so.6
#18 0x00007ffff6596630 in QCoreApplication::notifyInternal2(QObject*, QEvent*) () at /lib/x86_64-linux-gnu/libQt6Core.so.6
#19 0x00007ffff6597197 in QCoreApplicationPrivate::sendPostedEvents(QObject*, int, QThreadData*) () at /lib/x86_64-linux-gnu/libQt6Core.so.6
#20 0x00007ffff67a6db7 in ??? () at /lib/x86_64-linux-gnu/libQt6Core.so.6
#21 0x00007ffff59043c5 in ??? () at /lib/x86_64-linux-gnu/libglib-2.0.so.0
#22 0x00007ffff59065f7 in ??? () at /lib/x86_64-linux-gnu/libglib-2.0.so.0
#23 0x00007ffff5906d60 in g_main_context_iteration () at /lib/x86_64-linux-gnu/libglib-2.0.so.0
#24 0x00007ffff67a4323 in QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) () at /lib/x86_64-linux-gnu/libQt6Core.so.6
#25 0x00007ffff6598913 in QEventLoop::exec(QFlags<QEventLoop::ProcessEventsFlag>) () at /lib/x86_64-linux-gnu/libQt6Core.so.6
#26 0x00007ffff659a20a in QCoreApplication::exec() () at /lib/x86_64-linux-gnu/libQt6Core.so.6
#27 0x0000555555556c3a in main (argc=<optimized out>, argv=<optimized out>) at .../kernel-shark/src/kernelshark.cpp:154

呼び出し履歴の#0〜#1の間は呼び出し履歴すら消えていますので補完すると、

getValueStr()
  case TRACE_VIEW_COL_AUX:
    kshark_get_aux_info()
      interface->aux_info() : aux_info = tepdata_get_latency

こんな呼び出し順序になっています。コードをさらっと見た程度ではわかりませんでした。複雑すぎる。

KernelSharkの外に答えはあった

話を戻しましょう。Latencyの文字列を作成しているtepdata_get_latency()が呼んでいるtep_print_event()は、残念なことにKernelSharkの関数ではありません。libtraceevent（libtrace/libtraceevent.git - Library to parse raw trace event formats）で実装されています。

// libtraceevent/src/event-parse.c

/**
 * tep_print_event - Write various event information
 * @tep: a handle to the trace event parser context
 * @s: the trace_seq to write to
 * @record: The record to get the event from
 * @format: a printf format string. Supported event fileds:
 *	TEP_PRINT_PID, "%d" - event PID
 *	TEP_PRINT_CPU, "%d" - event CPU
 *	TEP_PRINT_COMM, "%s" - event command string
 *	TEP_PRINT_NAME, "%s" - event name
 *	TEP_PRINT_LATENCY, "%s" - event latency
 *	TEP_PRINT_TIME, %d - event time stamp. A divisor and precision
 *			can be specified as part of this format string:
 *			"%precision.divisord". Example:
 *			"%3.1000d" - divide the time by 1000 and print the first
 *			3 digits before the dot. Thus, the time stamp
 *			"123456000" will be printed as "123.456"
 *	TEP_PRINT_INFO, "%s" - event information. If any width is specified in
 *			the format string, the event information will be printed
 *			in raw format.
 * Writes the specified event information into @s.
 */
void tep_print_event(struct tep_handle *tep, struct trace_seq *s,
		     struct tep_record *record, const char *fmt, ...)
{
	struct print_event_type type;
	struct tep_event *event;
	char *current;
	char *format;
	char *str;
	int offset;
	va_list args;

	event = tep_find_event_by_record(tep, record);
	if (!event) {
		trace_seq_printf(s, "[UNKNOWN EVENT]");
		return;
	}

	str = current = format = strdup(fmt);
	if (!format)
		return;

	va_start(args, fmt);
	while (*current) {
		current = strchr(str, '%');
		if (!current) {
			trace_seq_puts(s, str);
			break;
		}
		memset(&type, 0, sizeof(type));
		offset = tep_print_event_param_type(current, &type);
		*current = '\0';
		trace_seq_puts(s, str);
		current += offset;
		switch (type.type) {
		case EVENT_TYPE_STRING:
			//★★★★"%s"を渡している、つまり文字列型なのでこちら
			print_string(tep, s, record, event,
				     va_arg(args, char*), &type);
			break;
		case EVENT_TYPE_INT:
			print_int(tep, s, record, event,
				  va_arg(args, int), &type);
			break;
		case EVENT_TYPE_UNKNOWN:
		default:
			trace_seq_printf(s, "[UNKNOWN TYPE]");
			break;
		}
		str = current;

	}
	va_end(args);
	free(format);
}

static void print_string(struct tep_handle *tep, struct trace_seq *s,
			 struct tep_record *record, struct tep_event *event,
			 const char *arg, struct print_event_type *type)
{
	const char *comm;
	int pid;

	if (strncmp(arg, TEP_PRINT_LATENCY, strlen(TEP_PRINT_LATENCY)) == 0) {
		//★★★★TEP_PRINT_LATENCYを渡しているのでこちら
		data_latency_format(tep, s, type->format, record);
	} else if (strncmp(arg, TEP_PRINT_COMM, strlen(TEP_PRINT_COMM)) == 0) {
		pid = parse_common_pid(tep, record->data);
		comm = find_cmdline(tep, pid);
		trace_seq_printf(s, type->format, comm);
	} else if (strncmp(arg, TEP_PRINT_INFO_RAW, strlen(TEP_PRINT_INFO_RAW)) == 0) {
		print_event_info(s, type->format, true, event, record);
	} else if (strncmp(arg, TEP_PRINT_INFO, strlen(TEP_PRINT_INFO)) == 0) {
		print_event_info(s, type->format, false, event, record);
	} else if  (strncmp(arg, TEP_PRINT_NAME, strlen(TEP_PRINT_NAME)) == 0) {
		trace_seq_printf(s, type->format, event->name);
	} else {
		trace_seq_printf(s, "[UNKNOWN TEP TYPE %s]", arg);
	}

}

/*
 * This parses out the Latency format (interrupts disabled,
 * need rescheduling, in hard/soft interrupt, preempt count
 * and lock depth) and places it into the trace_seq.
 */
static void data_latency_format(struct tep_handle *tep, struct trace_seq *s,
				char *format, struct tep_record *record)
{
	static int check_lock_depth = 1;
	static int check_migrate_disable = 1;
	static int lock_depth_exists;
	static int migrate_disable_exists;
	unsigned int lat_flags;
	struct trace_seq sq;
	unsigned int pc;
	int lock_depth = 0;
	int migrate_disable = 0;
	int hardirq;
	int softirq;
	void *data = record->data;

	trace_seq_init(&sq);
	lat_flags = parse_common_flags(tep, data);
	pc = parse_common_pc(tep, data);
	/* lock_depth may not always exist */
	if (lock_depth_exists)
		lock_depth = parse_common_lock_depth(tep, data);
	else if (check_lock_depth) {
		lock_depth = parse_common_lock_depth(tep, data);
		if (lock_depth < 0)
			check_lock_depth = 0;
		else
			lock_depth_exists = 1;
	}

	/* migrate_disable may not always exist */
	if (migrate_disable_exists)
		migrate_disable = parse_common_migrate_disable(tep, data);
	else if (check_migrate_disable) {
		migrate_disable = parse_common_migrate_disable(tep, data);
		if (migrate_disable < 0)
			check_migrate_disable = 0;
		else
			migrate_disable_exists = 1;
	}

	hardirq = lat_flags & TRACE_FLAG_HARDIRQ;
	softirq = lat_flags & TRACE_FLAG_SOFTIRQ;

	//★★★★1〜3桁目
	trace_seq_printf(&sq, "%c%c%c",
	       (lat_flags & TRACE_FLAG_IRQS_OFF) ? 'd' : '.',
	       (lat_flags & TRACE_FLAG_NEED_RESCHED) ?
	       'N' : (lat_flags &  TRACE_FLAG_NEED_RESCHED_LAZY) ? 'L' :'.',
	       (hardirq && softirq) ? 'H' :
	       hardirq ? 'h' : softirq ? 's' : '.');

	//★★★★4桁目
	if (pc & 0xf)
		trace_seq_printf(&sq, "%x", pc & 0xf);
	else
		trace_seq_printf(&sq, ".");

	//★★★★5桁目
	if (pc & 0xf0)
		trace_seq_printf(&sq, "%x", pc >> 4);
	else
		trace_seq_printf(&sq, ".");

	if (migrate_disable_exists) {
		if (migrate_disable < 0)
			trace_seq_printf(&sq, ".");
		else
			trace_seq_printf(&sq, "%d", migrate_disable);
	}

	if (lock_depth_exists) {
		if (lock_depth < 0)
			trace_seq_printf(&sq, ".");
		else
			trace_seq_printf(&sq, "%d", lock_depth);
	}

	if (sq.state == TRACE_SEQ__MEM_ALLOC_FAILED) {
		s->state = TRACE_SEQ__MEM_ALLOC_FAILED;
		return;
	}

	trace_seq_terminate(&sq);
	trace_seq_puts(s, sq.buffer);
	trace_seq_destroy(&sq);
	trace_seq_terminate(s);
}

やっと発見できました。pc（Preemption Counter）の上位4ビットでした。何を意味する値なのでしょう？また今度調べましょう。

KernelSharkのビルド方法

目次: Linux

KernelSharkの動きを見るためにビルドしました。ビルドにはlibtraceなんとか系、qt6、GLUTのライブラリ＆ヘッダをインストールする必要があります。ライブラリやヘッダが足りなければcmakeが怒ってきます。エラーメッセージと必要パッケージ名の対応がわかりづらいのは世の常です……。

$ sudo apt-get install -y \
  cmake ninja-build \
  libtraceevent-dev libtracefs-dev libtracecmd-dev \
  libjson-c-dev qt6-base-dev qt6-scxml-dev libglut-dev

$ git clone git://git.kernel.org/pub/scm/utils/trace-cmd/kernel-shark.git
$ cd kernel-shark

$ cmake -B _build -G Ninja
-- The C compiler identification is GNU 14.2.0
-- The CXX compiler identification is GNU 14.2.0
-- Detecting C compiler ABI info
-- Detecting C compiler ABI info - done
...略...

$ ninja -C _build
ninja: Entering directory `_build'
...略...
[110/110] Linking CXX shared library /...s/kernel-shark/lib/plugin-kvm_combo.so

警告がかなり出てますが、ビルドできてそうなので良しとします。バイナリはビルドディレクトリを無視して、ソースコード直下のbin/ディレクトリの下に生成されます。ビルドするとソースコードディレクトリが汚染される謎の作りです。

動作チェック

動作確認します。まずはtrace-cmdで適当にイベントを取得します。特に何も指定しなければtrace.datにイベント情報が書き込まれるはずです。

$ sudo trace-cmd start -e sched_switch
$ sudo trace-cmd extract

$ bin/kernelshark ./trace.dat

バイナリファイルはbin/kernelsharkです。引数にファイル名を渡して実行するとこんな感じの画面が表示されるはずです。

KernelSharkの画面の例

これでgdbでデバッグしたり、コードを変更してログを入れたりする準備ができました。よかったよかった。

ジャガーさんのパワステから異音

目次: 車

だいたい10km/h前後の低速走行時にハンドルを切ると「グワ、グワワ」みたいな小さいうなり音が聞こえるようになりました。アヒルが住んでいるのか？

今のところ特に動作に支障はありませんが、壊れる前兆なのでしょうか。パワステ壊れたら高そうだ、嫌だなあ。

ジャガーXEのタイヤ交換

目次: 車

タイヤのメーカーが左前だけ違うのと、溝の残りが4mmくらいで結構減ってしまっていたので、車を買ったばかりですがタイヤ交換することにしました。タイヤのメーカーが違う理由は、おそらく前のオーナーさんが片方パンクしたのを応急処置的に変えたのだと思われます。

新しいタイヤはレガシィにも付けていたFALKEN AZENIS FK520L（製品サイト）にしました。ミシュランやヨコハマと比べればFALKENはお買い得価格ですが、それでも工賃その他もろもろ込みで19万円くらいになりました。高いよ〜！

理由は明らかで前タイヤは235/35R20、後タイヤは265/30R20でめちゃデカくて扁平だからです。選択肢が少ないし、値段も高いし、タイヤ交換してくれるお店も少ないし、辛さがすごい。これで純正サイズ、外車の維持費が高いといわれる理由がわかりました……。

タイヤ交換の時にFK520L 235/35R20 92YはXL（エクストラロード）規格なので、純正の指定空気圧より空気圧を上げておきました。と言われましたが、純正タイヤのPIRELLI P ZERO 235/35R20 92Yも同じXL規格なので、実は空気圧は指定通りでいいのでは？？上げすぎで真ん中ばっかり減ったら嫌だなあ。

不遇のFALKENブランド

住友ゴム工業は日本でDUNLOP、FALKENの両ブランドを展開しています。DUNLOPのほうが名の通りが良いから？なのか、自社ブランドのFALKENブランドはやや雑な扱いを受けているようです。例えば両ブランドの同クラスの製品であるDUNLOP SPORT MAXX RSとAZENIS FK520Lのサイトを見比べると扱いの差がわかると思います。でもFALKENは名品だと思いますね、ラインナップ広いしコスパは断然良いと思います。