Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Sentry への performance 報告が動いていなさそう #61

Open
kory33 opened this issue Jun 18, 2023 · 7 comments
Open

Sentry への performance 報告が動いていなさそう #61

kory33 opened this issue Jun 18, 2023 · 7 comments
Labels
bug Something isn't working

Comments

@kory33
Copy link
Member

kory33 commented Jun 18, 2023

ingestor を起動すると sentry client が enable されるが、
image

終了時に performance 情報を Sentry に送信していない。
image

終了時より前、 root span を出るタイミングにて sentry client は Sentry に performance 情報を送信開始し、sentry client が drop されるタイミングで Sentry へのリクエストを flush しきるはずなので、何かがおかしい。

今のところ、アプリケーション側の問題なのか seichi_infra での設定による問題なのかは不明 (ローカルで、データソースを Mock に切り替えたうえで実行したところ正常に報告されることを確認している)。

@kory33 kory33 added the bug Something isn't working label Jun 18, 2023
@kory33
Copy link
Member Author

kory33 commented Jun 18, 2023

まずは、 seichi-game-data-server をローカルで立ち上げるなり、プロダクション環境に port forwarding するなりして、ローカル環境の Docker 内で (現在 CronJob が利用しているものと同じイメージを用いて) 問題が再現するかどうかを確かめてみたい。

もし再現すれば、 CrobJob が利用しているイメージでは無く、直接 cargo run したときと挙動を比較したい。

@kory33
Copy link
Member Author

kory33 commented Jun 18, 2023

GiganticMinecraft/seichi_infra#1095 で直接 seichi-game-data-server を (今のところ僕のみ) 見れるようにしたので、ローカルから繋いで (DB はローカルで建てて) デバッグしてみたが、 cargo run ingestor しても Sentry へのパフォーマンス報告が飛ばなかった…
image

@kory33
Copy link
Member Author

kory33 commented Jun 18, 2023

パフォーマンス報告とエラー報告の両方が動いた例:

fetch_and_record_all() の直後に panic! すると、トレース情報がすべて送られ、panic の内容も送信された。Sentry には event が作成され、panic! 内容も issue として記録された。

image
(送信しているデータ量を鑑みるに、一つ目の API コールがおそらくトレース情報、次のものがエラー情報)

この panic! を消すとエラー報告が消えるだけでなくパフォーマンス報告も消える。_sentry_client_guard を明示的に drop したり、その後 5s sleep() してみたりしても変わらない。どうして???

@kory33
Copy link
Member Author

kory33 commented Jun 19, 2023

Mock upstream repository を用いてパフォーマンス報告が動いた例

gRPC で繋ぎに行っている seichi-game-data-server (client 実装, 初期化) を次のような mock repository で置き換えて

pub struct MockUpstreamRepository;
#[async_trait::async_trait]
impl<S> PlayerStatsRepository<S> for MockUpstreamRepository
where
    S: Send + 'static,
{
    async fn fetch_stats_snapshot_of_all_players(&self) -> anyhow::Result<StatsSnapshot<S>> {
        Ok(StatsSnapshot {
            utc_timestamp: chrono::Utc::now(),
            player_stats: HashMap::new(),
        })
    }
}

それを stats_repository_impl で利用するようにすると

async fn stats_repository_impl() -> anyhow::Result<
    impl PlayerStatsRepository<BreakCount>
        + PlayerStatsRepository<BuildCount>
        + PlayerStatsRepository<PlayTicks>
        + PlayerStatsRepository<VoteCount>,
> {
    Ok(infra_upstream_repository_impl::MockUpstreamRepository {})
}

なんと動く (該当 transaction)。

image
image

そうはならんやろ

@kory33
Copy link
Member Author

kory33 commented Jun 19, 2023

終了直前に先に .flush してもダメっぽい

image

@kory33
Copy link
Member Author

kory33 commented Jun 21, 2023

より詳細な切り分け

gRPC クライアントを初期化するかしないかで Sentry に performance 報告が飛ぶか飛ばないかが分かれてる?

例えば、これだと

#[tracing::instrument]
async fn fetch_and_record_all() -> anyhow::Result<()> {
    let stats_repository = stats_repository_impl().await?;

    Ok(())
}

次のようになり、Sentry に API コールは行われず、transaction も生えないのだが、

2023-06-21T20:42:03.280518Z DEBUG sentry: enabled sentry client for DSN https://20ce98e4b5304846be70f3bd78a6a588:[email protected]/9    
2023-06-21T20:42:05.038181Z  INFO pprof::profiler: starting cpu profiler    
2023-06-21T20:42:05.038295Z  INFO pprof::profiler: stopping cpu profiler    
2023-06-21T20:42:05.083329Z  INFO pprof::profiler: starting cpu profiler    
2023-06-21T20:42:05.083824Z DEBUG hyper::client::connect::dns: resolving host="localhost"
2023-06-21T20:42:05.084143Z DEBUG fetch_and_record_all: hyper::client::connect::http: connecting to 127.0.0.1:50051
2023-06-21T20:42:05.084655Z DEBUG fetch_and_record_all: hyper::client::connect::http: connected to 127.0.0.1:50051
2023-06-21T20:42:05.084801Z DEBUG fetch_and_record_all: h2::client: binding client connection
2023-06-21T20:42:05.084895Z DEBUG fetch_and_record_all: h2::client: client connection bound
2023-06-21T20:42:05.085026Z DEBUG fetch_and_record_all: h2::codec::framed_write: send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
2023-06-21T20:42:05.085807Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
2023-06-21T20:42:05.085933Z DEBUG sentry: dropping client guard -> disposing client    
2023-06-21T20:42:05.086196Z DEBUG sentry: client close; request transport to shut down    
2023-06-21T20:42:05.086441Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }
2023-06-21T20:42:05.086584Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::proto::connection: Connection::poll; connection error error=GoAway(b"", NO_ERROR, Library)
2023-06-21T20:42:05.088417Z  INFO pprof::profiler: stopping cpu profiler    
2023-06-21T20:42:05.122591Z DEBUG sentry: the profile is being dropped because it contains no samples

何もせずにすぐ抜けると

#[tracing::instrument]
async fn fetch_and_record_all() -> anyhow::Result<()> {
    Ok(())
}

transaction が生える

2023-06-21T20:40:41.090017Z DEBUG sentry: enabled sentry client for DSN https://20ce98e4b5304846be70f3bd78a6a588:[email protected]/9    
2023-06-21T20:40:43.069370Z  INFO pprof::profiler: starting cpu profiler    
2023-06-21T20:40:43.069451Z  INFO pprof::profiler: stopping cpu profiler    
2023-06-21T20:40:43.120563Z  INFO pprof::profiler: starting cpu profiler    
2023-06-21T20:40:43.122267Z  INFO pprof::profiler: stopping cpu profiler    
2023-06-21T20:40:43.140650Z DEBUG sentry: the profile is being dropped because it contains no samples    
2023-06-21T20:40:43.140791Z DEBUG sentry: dropping client guard -> disposing client    
2023-06-21T20:40:43.141051Z DEBUG sentry: client close; request transport to shut down    
2023-06-21T20:40:43.141231Z DEBUG reqwest::connect: starting new connection: https://sentry.onp.admin.seichi.click/    
2023-06-21T20:40:43.141446Z DEBUG hyper::client::connect::dns: resolving host="sentry.onp.admin.seichi.click"
2023-06-21T20:40:43.165811Z DEBUG hyper::client::connect::http: connecting to 104.26.0.215:443
2023-06-21T20:40:43.177320Z DEBUG hyper::client::connect::http: connected to 104.26.0.215:443
2023-06-21T20:40:43.193593Z DEBUG hyper::proto::h1::io: flushed 1072 bytes
2023-06-21T20:40:44.245718Z DEBUG hyper::proto::h1::io: parsed 20 headers
2023-06-21T20:40:44.245806Z DEBUG hyper::proto::h1::conn: incoming body is content-length (41 bytes)
2023-06-21T20:40:44.245950Z DEBUG hyper::proto::h1::conn: incoming body completed
2023-06-21T20:40:44.246145Z DEBUG hyper::client::pool: pooling idle connection for ("https", sentry.onp.admin.seichi.click)
2023-06-21T20:40:44.246334Z DEBUG sentry: Get response: `{"id":"a241079564c245079176e5dfd1c26679"}`

@kory33
Copy link
Member Author

kory33 commented Jun 21, 2023

動いた例

main 抜ける前に tokio::time::sleep(Duration::from_secs(1)).await したら正常に動作することを確認できた (drop されるよりも前に送信を開始してそう)
次のような感じ

#[tokio::main]
async fn main() -> Result<(), Box<dyn std::error::Error>> {
    ...

    fetch_and_record_all().await?;

    tokio::time::sleep(Duration::from_secs(1)).await; // <---

    Ok(())
}
実行ログ
2023-06-21T21:54:31.425612Z DEBUG sentry: enabled sentry client for DSN https://20ce98e4b5304846be70f3bd78a6a588:[email protected]/9    
2023-06-21T21:54:33.110040Z  INFO pprof::profiler: starting cpu profiler    
2023-06-21T21:54:33.110119Z  INFO pprof::profiler: stopping cpu profiler    
2023-06-21T21:54:33.154880Z  INFO pprof::profiler: starting cpu profiler    
2023-06-21T21:54:33.155331Z DEBUG hyper::client::connect::dns: resolving host="localhost"
2023-06-21T21:54:33.155652Z DEBUG fetch_and_record_all: hyper::client::connect::http: connecting to 127.0.0.1:50051
2023-06-21T21:54:33.156041Z DEBUG fetch_and_record_all: hyper::client::connect::http: connected to 127.0.0.1:50051
2023-06-21T21:54:33.156156Z DEBUG fetch_and_record_all: h2::client: binding client connection
2023-06-21T21:54:33.156298Z DEBUG fetch_and_record_all: h2::client: client connection bound
2023-06-21T21:54:33.156431Z DEBUG fetch_and_record_all: h2::codec::framed_write: send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
2023-06-21T21:54:33.157054Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
2023-06-21T21:54:33.158370Z DEBUG fetch_and_record_all:fetch_and_record: tower::buffer::worker: service.ready=true processing request
2023-06-21T21:54:33.158970Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
2023-06-21T21:54:33.159249Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=Data { stream_id: StreamId(1) }
2023-06-21T21:54:33.159413Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
2023-06-21T21:54:34.487714Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=Settings { flags: (0x1: ACK) }
2023-06-21T21:54:34.733917Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::proto::settings: received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
2023-06-21T21:54:36.077737Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(1), size_increment: 704512 }
2023-06-21T21:54:36.315852Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(1), size_increment: 704512 }
2023-06-21T21:54:36.384400Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 1753088 }
2023-06-21T21:54:36.443277Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(1), size_increment: 704512 }
2023-06-21T21:54:39.634439Z DEBUG fetch_and_record_all:fetch_and_record: tower::buffer::worker: service.ready=true processing request
2023-06-21T21:54:39.635380Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=Headers { stream_id: StreamId(3), flags: (0x4: END_HEADERS) }
2023-06-21T21:54:39.635523Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=Data { stream_id: StreamId(3) }
2023-06-21T21:54:39.635642Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=Data { stream_id: StreamId(3), flags: (0x1: END_STREAM) }
2023-06-21T21:54:40.267847Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(3), size_increment: 704512 }
2023-06-21T21:54:40.279570Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 1752001 }
2023-06-21T21:54:40.344615Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(3), size_increment: 704512 }
2023-06-21T21:54:40.517687Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(3), size_increment: 704512 }
2023-06-21T21:54:40.567594Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 1753088 }
2023-06-21T21:54:43.529077Z DEBUG fetch_and_record_all:fetch_and_record: tower::buffer::worker: service.ready=true processing request
2023-06-21T21:54:43.529776Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=Headers { stream_id: StreamId(5), flags: (0x4: END_HEADERS) }
2023-06-21T21:54:43.529990Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=Data { stream_id: StreamId(5) }
2023-06-21T21:54:43.530168Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=Data { stream_id: StreamId(5), flags: (0x1: END_STREAM) }
2023-06-21T21:54:44.120514Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(5), size_increment: 704512 }
2023-06-21T21:54:44.196803Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(5), size_increment: 704512 }
2023-06-21T21:54:44.223841Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 1748344 }
2023-06-21T21:54:44.390480Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(5), size_increment: 704512 }
2023-06-21T21:54:47.190520Z DEBUG fetch_and_record_all:fetch_and_record: tower::buffer::worker: service.ready=true processing request
2023-06-21T21:54:47.190991Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=Headers { stream_id: StreamId(7), flags: (0x4: END_HEADERS) }
2023-06-21T21:54:47.191136Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=Data { stream_id: StreamId(7) }
2023-06-21T21:54:47.191295Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=Data { stream_id: StreamId(7), flags: (0x1: END_STREAM) }
2023-06-21T21:54:47.775094Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 1749897 }
2023-06-21T21:54:47.782016Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(7), size_increment: 704512 }
2023-06-21T21:54:47.858661Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(7), size_increment: 704512 }
2023-06-21T21:54:48.034082Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(7), size_increment: 704512 }
2023-06-21T21:54:48.069121Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 1753088 }
2023-06-21T21:54:50.551335Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::codec::framed_write: send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }
2023-06-21T21:54:50.551492Z DEBUG fetch_and_record_all:Connection{peer=Client}: h2::proto::connection: Connection::poll; connection error error=GoAway(b"", NO_ERROR, Library)
2023-06-21T21:54:50.653804Z  INFO pprof::profiler: stopping cpu profiler    
2023-06-21T21:54:50.704503Z DEBUG reqwest::connect: starting new connection: https://sentry.onp.admin.seichi.click/    
2023-06-21T21:54:50.704824Z DEBUG hyper::client::connect::dns: resolving host="sentry.onp.admin.seichi.click"
2023-06-21T21:54:50.726112Z DEBUG hyper::client::connect::http: connecting to 104.26.1.215:443
2023-06-21T21:54:50.737354Z DEBUG hyper::client::connect::http: connected to 104.26.1.215:443
2023-06-21T21:54:50.754019Z DEBUG hyper::proto::h1::io: flushed 16384 bytes
2023-06-21T21:54:50.754130Z DEBUG hyper::proto::h1::io: flushed 16384 bytes
2023-06-21T21:54:50.766463Z DEBUG hyper::proto::h1::io: flushed 32768 bytes
2023-06-21T21:54:50.766580Z DEBUG hyper::proto::h1::io: flushed 16384 bytes
2023-06-21T21:54:50.778473Z DEBUG hyper::proto::h1::io: flushed 32768 bytes
2023-06-21T21:54:50.778630Z DEBUG hyper::proto::h1::io: flushed 16384 bytes
2023-06-21T21:54:50.778651Z DEBUG hyper::proto::h1::io: flushed 16384 bytes
2023-06-21T21:54:50.788299Z DEBUG hyper::proto::h1::io: flushed 32768 bytes
2023-06-21T21:54:50.788362Z DEBUG hyper::proto::h1::io: flushed 16384 bytes
2023-06-21T21:54:50.788405Z DEBUG hyper::proto::h1::io: flushed 16384 bytes
2023-06-21T21:54:50.788445Z DEBUG hyper::proto::h1::io: flushed 16384 bytes
2023-06-21T21:54:50.788484Z DEBUG hyper::proto::h1::io: flushed 16384 bytes
2023-06-21T21:54:50.829605Z DEBUG hyper::proto::h1::io: flushed 32768 bytes
2023-06-21T21:54:50.829677Z DEBUG hyper::proto::h1::io: flushed 16384 bytes
2023-06-21T21:54:50.829696Z DEBUG hyper::proto::h1::io: flushed 16384 bytes
2023-06-21T21:54:50.829711Z DEBUG hyper::proto::h1::io: flushed 16384 bytes
2023-06-21T21:54:50.862237Z DEBUG hyper::proto::h1::io: flushed 32768 bytes
2023-06-21T21:54:50.862299Z DEBUG hyper::proto::h1::io: flushed 16384 bytes
2023-06-21T21:54:50.862319Z DEBUG hyper::proto::h1::io: flushed 16384 bytes
2023-06-21T21:54:50.891305Z DEBUG hyper::proto::h1::io: flushed 32768 bytes
2023-06-21T21:54:50.891369Z DEBUG hyper::proto::h1::io: flushed 16384 bytes
2023-06-21T21:54:50.891390Z DEBUG hyper::proto::h1::io: flushed 16384 bytes
2023-06-21T21:54:50.891405Z DEBUG hyper::proto::h1::io: flushed 16384 bytes
2023-06-21T21:54:50.891443Z DEBUG hyper::proto::h1::io: flushed 16384 bytes
2023-06-21T21:54:50.891484Z DEBUG hyper::proto::h1::io: flushed 16384 bytes
2023-06-21T21:54:50.891504Z DEBUG hyper::proto::h1::io: flushed 16384 bytes
2023-06-21T21:54:50.891563Z DEBUG hyper::proto::h1::io: flushed 10578 bytes
2023-06-21T21:54:51.552294Z DEBUG sentry: dropping client guard -> disposing client    
2023-06-21T21:54:51.552564Z DEBUG sentry: client close; request transport to shut down    
2023-06-21T21:54:52.954326Z DEBUG hyper::proto::h1::io: parsed 20 headers
2023-06-21T21:54:52.954392Z DEBUG hyper::proto::h1::conn: incoming body is content-length (41 bytes)
2023-06-21T21:54:52.954449Z DEBUG hyper::proto::h1::conn: incoming body completed
2023-06-21T21:54:52.954590Z DEBUG hyper::client::pool: pooling idle connection for ("https", sentry.onp.admin.seichi.click)
2023-06-21T21:54:52.954695Z DEBUG sentry: Get response: `{"id":"83aa8d49714042dea6c1627195df1899"}`

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

1 participant