From 6f399dc6bf5e8951391493044e6cb6b11d395a57 Mon Sep 17 00:00:00 2001 From: Cristian Greco Date: Thu, 12 Feb 2026 11:59:52 +0100 Subject: [PATCH] fix(database_observability.mysql): Skip wait events with `NULL` timer_wait (#5478) ### Brief description of Pull Request Do not log wait events with NULL timer_wait (currently logged as "0ms" duration), as they do not provide meaningful information. ### Pull Request Details Avoid logs like ``` wait_event_name="wait/io/socket/sql/client_connection" wait_object_type="SOCKET" wait_time="0.000000ms" sql_text="COMMIT" ``` ### Issue(s) fixed by this Pull Request ### Notes to the Reviewer ### PR Checklist - [ ] Documentation added - [x] Tests updated - [ ] Config converters updated (cherry picked from commit 48750e5848b5bcae2f87807ffd02b46249c0aebc) --- .../mysql/collector/query_samples.go | 2 +- .../mysql/collector/query_samples_test.go | 95 +++++++++++++++++++ 2 files changed, 96 insertions(+), 1 deletion(-) diff --git a/internal/component/database_observability/mysql/collector/query_samples.go b/internal/component/database_observability/mysql/collector/query_samples.go index 0fa561c21eb..67a7d0e9805 100644 --- a/internal/component/database_observability/mysql/collector/query_samples.go +++ b/internal/component/database_observability/mysql/collector/query_samples.go @@ -375,7 +375,7 @@ func (c *QuerySamples) fetchQuerySamples(ctx context.Context) error { ) } - if row.WaitEventID.Valid { + if row.WaitEventID.Valid && row.WaitTime.Valid { waitTime := picosecondsToMilliseconds(row.WaitTime.Float64) waitLogMessage := fmt.Sprintf( `schema="%s" thread_id="%s" digest="%s" event_id="%s" wait_event_id="%s" wait_end_event_id="%s" wait_event_name="%s" wait_object_name="%s" wait_object_type="%s" wait_time="%fms"`, diff --git a/internal/component/database_observability/mysql/collector/query_samples_test.go b/internal/component/database_observability/mysql/collector/query_samples_test.go index ce6fb66c39f..494222f7681 100644 --- a/internal/component/database_observability/mysql/collector/query_samples_test.go +++ b/internal/component/database_observability/mysql/collector/query_samples_test.go @@ -319,6 +319,101 @@ func TestQuerySamples_WaitEvents(t *testing.T) { assert.Equal(t, "level=\"info\" schema=\"some_schema\" thread_id=\"890\" digest=\"some_digest\" event_id=\"123\" wait_event_id=\"124\" wait_end_event_id=\"124\" wait_event_name=\"wait/io/file/innodb/innodb_data_file\" wait_object_name=\"wait_object_name\" wait_object_type=\"wait_object_type\" wait_time=\"0.100000ms\"", lokiEntries[1].Line) }) + t.Run("wait event with NULL timer_wait is skipped", func(t *testing.T) { + db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherEqual)) + require.NoError(t, err) + defer db.Close() + + lokiClient := loki.NewCollectingHandler() + + collector, err := NewQuerySamples(QuerySamplesArguments{ + DB: db, + EngineVersion: latestCompatibleVersion, + CollectInterval: time.Second, + EntryHandler: lokiClient, + Logger: log.NewLogfmtLogger(os.Stderr), + }) + require.NoError(t, err) + require.NotNil(t, collector) + + mock.ExpectQuery(selectUptime).WithoutArgs().RowsWillBeClosed().WillReturnRows(sqlmock.NewRows([]string{"uptime"}).AddRow("1")) + mock.ExpectQuery(selectNowAndUptime).WithoutArgs().WillReturnRows(sqlmock.NewRows([]string{"now", "uptime"}).AddRow(5, 1)) + mock.ExpectQuery(fmt.Sprintf(selectQuerySamples, cpuTimeField+maxControlledMemoryField+maxTotalMemoryField, exclusionClause, digestTextNotNullClause, endOfTimeline)).WithArgs( + 1e12, + 1e12, + ).RowsWillBeClosed(). + WillReturnRows( + sqlmock.NewRows([]string{ + "statements.CURRENT_SCHEMA", + "statements.THREAD_ID", + "statements.EVENT_ID", + "statements.END_EVENT_ID", + "statements.DIGEST", + "statements.TIMER_END", + "statements.TIMER_WAIT", + "statements.ROWS_EXAMINED", + "statements.ROWS_SENT", + "statements.ROWS_AFFECTED", + "statements.ERRORS", + "waits.event_id", + "waits.end_event_id", + "waits.event_name", + "waits.object_name", + "waits.object_type", + "waits.timer_wait", + "statements.CPU_TIME", + "statements.MAX_CONTROLLED_MEMORY", + "statements.MAX_TOTAL_MEMORY", + }).AddRows( + []driver.Value{ + "some_schema", + "890", + "123", + "234", + "some_digest", + "70000000", + "20000000", + "5", + "5", + "0", + "0", + "124", + "124", + "wait/io/file/innodb/innodb_data_file", + "wait_object_name", + "wait_object_type", + nil, // NULL timer_wait + "10000000", + "456", + "457", + }, + ), + ) + + err = collector.Start(t.Context()) + require.NoError(t, err) + + // Only the query sample should be collected, the wait event should be skipped + require.Eventually(t, func() bool { + return len(lokiClient.Received()) == 1 + }, 5*time.Second, 100*time.Millisecond) + + collector.Stop() + lokiClient.Stop() + + require.Eventually(t, func() bool { + return collector.Stopped() + }, 5*time.Second, 100*time.Millisecond) + + err = mock.ExpectationsWereMet() + require.NoError(t, err) + + lokiEntries := lokiClient.Received() + require.Len(t, lokiEntries, 1) + assert.Equal(t, model.LabelSet{"op": OP_QUERY_SAMPLE}, lokiEntries[0].Labels) + assert.Equal(t, "level=\"info\" schema=\"some_schema\" thread_id=\"890\" event_id=\"123\" end_event_id=\"234\" digest=\"some_digest\" rows_examined=\"5\" rows_sent=\"5\" rows_affected=\"0\" errors=\"0\" max_controlled_memory=\"456b\" max_total_memory=\"457b\" cpu_time=\"0.010000ms\" elapsed_time=\"0.020000ms\" elapsed_time_ms=\"0.020000ms\"", lokiEntries[0].Line) + }) + t.Run("query sample and multiple wait events are collected", func(t *testing.T) { db, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherEqual)) require.NoError(t, err)