limingjie/OmniSocketGo
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

feat: 增加日志模块

Browse Source
This commit is contained in:
Mock
2026-04-18 12:52:39 +08:00
parent b700dab484
commit 212459a8e4
18 changed files with 938 additions and 42 deletions
Download Patch File Download Diff File Expand all files Collapse all files

8
src/kcp_session_stats.c
View File

@@ -156,10 +156,18 @@ int kcp_session_stats_log(kcp_session_stats_logger_t *logger, const kcp_session_
kcp_session_stats_appendf(&line, &line_len, ",\"srtt_ms\":%d", record->srtt_ms) != 0) {
goto cleanup;
}
if (record->has_min_srtt_ms &&
kcp_session_stats_appendf(&line, &line_len, ",\"min_srtt_ms\":%d", record->min_srtt_ms) != 0) {
goto cleanup;
}
if (record->has_srttvar_ms &&
kcp_session_stats_appendf(&line, &line_len, ",\"srttvar_ms\":%d", record->srttvar_ms) != 0) {
goto cleanup;
}
if (record->has_last_feedback_age_ms &&
kcp_session_stats_appendf(&line, &line_len, ",\"last_feedback_age_ms\":%u", record->last_feedback_age_ms) != 0) {
goto cleanup;
}
if (record->has_snd_wnd &&
kcp_session_stats_appendf(&line, &line_len, ",\"snd_wnd\":%u", record->snd_wnd) != 0) {
goto cleanup;

13
src/peer_kcp_client.c
View File

@@ -477,6 +477,16 @@ int kcp_client_send_text(kcp_client_t *client, const char *to, const char *text)
}
int kcp_client_send_binary(kcp_client_t *client, const char *to, const void *data, size_t data_len) {
return kcp_client_send_binary_with_id(client, to, data, data_len, NULL);
}
int kcp_client_send_binary_with_id(
kcp_client_t *client,
const char *to,
const void *data,
size_t data_len,
uint64_t *out_id
) {
message_t msg;
uint64_t id;
@@ -508,6 +518,9 @@ int kcp_client_send_binary(kcp_client_t *client, const char *to, const void *dat
protocol_message_clear(&msg);
return -1;
}
if (out_id != NULL) {
*out_id = id;
}
protocol_message_clear(&msg);
return 0;
}

2
src/server_kcp_hub.c
View File

@@ -228,7 +228,9 @@ static int kcp_hub_add_runtime_stats_json(cJSON *object, const kcp_runtime_stats
cJSON_AddNumberToObject(object, "conv", (double) stats->conv) == NULL ||
cJSON_AddNumberToObject(object, "rto_ms", (double) stats->rto_ms) == NULL ||
cJSON_AddNumberToObject(object, "srtt_ms", (double) stats->srtt_ms) == NULL ||
cJSON_AddNumberToObject(object, "min_srtt_ms", (double) stats->min_srtt_ms) == NULL ||
cJSON_AddNumberToObject(object, "srttvar_ms", (double) stats->srttvar_ms) == NULL ||
cJSON_AddNumberToObject(object, "last_feedback_age_ms", (double) stats->last_feedback_age_ms) == NULL ||
cJSON_AddNumberToObject(object, "snd_wnd", (double) stats->snd_wnd) == NULL ||
cJSON_AddNumberToObject(object, "rmt_wnd", (double) stats->rmt_wnd) == NULL ||
cJSON_AddNumberToObject(object, "inflight", (double) stats->inflight) == NULL ||

32
src/transport_kcp.c
View File

@@ -72,6 +72,8 @@ struct kcp_conn {
uint64_t pending_in_errs;
uint64_t pending_kcp_in_errs;
protocol_frame_decoder_t decoder;
int32_t min_srtt_ms;
uint32_t last_feedback_ms;
uint8_t scratch[KCP_RECV_CHUNK_SIZE];
latency_logger_t *logger;
char node_role[OMNI_MAX_NODE_ROLE];
@@ -307,6 +309,26 @@ static uint64_t kcp_counter_diff(uint64_t previous, uint64_t current) {
return current < previous ? 0 : current - previous;
}
static void kcp_conn_update_min_srtt_locked(kcp_conn_t *conn) {
int32_t srtt_ms;
if (conn == NULL || conn->kcp == NULL) {
return;
}
srtt_ms = conn->kcp->rx_srtt;
if (srtt_ms > 0 && (conn->min_srtt_ms <= 0 || srtt_ms < conn->min_srtt_ms)) {
conn->min_srtt_ms = srtt_ms;
}
}
static void kcp_conn_note_feedback_locked(kcp_conn_t *conn) {
if (conn == NULL) {
return;
}
conn->last_feedback_ms = omni_now_millis32();
kcp_conn_update_min_srtt_locked(conn);
}
static int kcp_process_sampler_matches(const kcp_process_sampler_t *sampler, kcp_session_stats_logger_t *logger, const char *node_role, const char *node_id, int stats_interval_ms) {
if (sampler == NULL) {
return 0;
@@ -1093,8 +1115,13 @@ static void kcp_log_session_snapshot(kcp_conn_t *conn, const char *reason) {
record.rto_ms = conn->kcp->rx_rto;
record.has_srtt_ms = 1;
record.srtt_ms = conn->kcp->rx_srtt;
kcp_conn_update_min_srtt_locked(conn);
record.has_min_srtt_ms = conn->min_srtt_ms > 0;
record.min_srtt_ms = conn->min_srtt_ms;
record.has_srttvar_ms = 1;
record.srttvar_ms = conn->kcp->rx_rttval;
record.has_last_feedback_age_ms = conn->last_feedback_ms != 0;
record.last_feedback_age_ms = conn->last_feedback_ms == 0 ? 0 : (omni_now_millis32() - conn->last_feedback_ms);
record.has_snd_wnd = 1;
record.snd_wnd = conn->kcp->snd_wnd;
record.has_rmt_wnd = 1;
@@ -1268,6 +1295,7 @@ static void *kcp_client_recv_thread_main(void *arg) {
if (ikcp_input(conn->kcp, (const char *) buffer, n) != 0) {
kcp_conn_record_error(conn);
} else {
kcp_conn_note_feedback_locked(conn);
kcp_conn_record_input(conn, (int) n, segment_count);
}
pthread_mutex_unlock(&conn->kcp_mu);
@@ -1630,6 +1658,7 @@ static void *kcp_listener_recv_thread_main(void *arg) {
if (ikcp_input(conn->kcp, (const char *) buffer, n) != 0) {
kcp_conn_record_error(conn);
} else {
kcp_conn_note_feedback_locked(conn);
kcp_conn_record_input(conn, (int) n, segment_count);
}
pthread_mutex_unlock(&conn->kcp_mu);
@@ -1907,7 +1936,10 @@ void kcp_conn_runtime_stats_snapshot(kcp_conn_t *conn, kcp_runtime_stats_t *out_
out_stats->conv = conn->kcp->conv;
out_stats->rto_ms = conn->kcp->rx_rto;
out_stats->srtt_ms = conn->kcp->rx_srtt;
kcp_conn_update_min_srtt_locked(conn);
out_stats->min_srtt_ms = conn->min_srtt_ms;
out_stats->srttvar_ms = conn->kcp->rx_rttval;
out_stats->last_feedback_age_ms = conn->last_feedback_ms == 0 ? 0 : (omni_now_millis32() - conn->last_feedback_ms);
out_stats->snd_wnd = conn->kcp->snd_wnd;
out_stats->rmt_wnd = conn->kcp->rmt_wnd;
out_stats->inflight = conn->kcp->snd_nxt - conn->kcp->snd_una;

207
src/video_pipeline.c
View File

@@ -46,6 +46,7 @@ typedef struct video_sender {
char target_peer[OMNI_MAX_PEER_ID];
uint8_t *send_buffer;
size_t send_buffer_cap;
uint64_t next_frame_seq;
} video_sender_t;
static int video_pipeline_stop_requested(volatile sig_atomic_t *stop_requested) {
@@ -212,6 +213,7 @@ void video_pipeline_config_init(video_pipeline_config_t *config) {
config->hard_backpressure_hold_ms = VIDEO_HARD_BACKPRESSURE_HOLD_MS_DEFAULT;
config->frame_stall_reconnect_ms = VIDEO_DEFAULT_FRAME_STALL_RECONNECT_MS;
config->stats_logger = NULL;
config->stage_logger = NULL;
config->stats_interval_ms = 1000;
}
@@ -272,6 +274,8 @@ void video_pipeline_stats_snapshot(video_pipeline_stats_t *stats, video_pipeline
out_stats->backlog_resets = stats->backlog_resets;
out_stats->last_frame_bytes = stats->last_frame_bytes;
out_stats->last_backlog_segments = stats->last_backlog_segments;
out_stats->last_capture_to_send_ms = stats->last_capture_to_send_ms;
out_stats->avg_capture_to_send_ms = stats->avg_capture_to_send_ms;
out_stats->connected = stats->connected;
snprintf(out_stats->last_error, sizeof(out_stats->last_error), "%s", stats->last_error);
snprintf(out_stats->last_backlog_reason, sizeof(out_stats->last_backlog_reason), "%s", stats->last_backlog_reason);
@@ -644,10 +648,12 @@ static int video_sender_drain_pending_messages(video_sender_t *sender) {
static int video_sender_send_packet(
video_sender_t *sender,
const AVPacket *encoded_pkt,
const video_pipeline_packet_metadata_t *metadata
const video_pipeline_packet_metadata_t *metadata,
uint64_t *out_frame_seq
) {
uint8_t *payload;
size_t payload_len;
uint64_t frame_seq;
int rc;
if (sender == NULL || sender->client == NULL || encoded_pkt == NULL || metadata == NULL) {
@@ -655,18 +661,31 @@ static int video_sender_send_packet(
return -1;
}
payload_len = (size_t) encoded_pkt->size + sizeof(*metadata);
frame_seq = sender->next_frame_seq + 1U;
payload_len = 8U + (size_t) encoded_pkt->size + sizeof(*metadata);
if (video_sender_ensure_buffer_capacity(sender, payload_len) != 0) {
return -1;
}
payload = sender->send_buffer;
memcpy(payload, encoded_pkt->data, (size_t) encoded_pkt->size);
memcpy(payload + encoded_pkt->size, metadata, sizeof(*metadata));
payload[0] = (uint8_t) (frame_seq >> 56);
payload[1] = (uint8_t) (frame_seq >> 48);
payload[2] = (uint8_t) (frame_seq >> 40);
payload[3] = (uint8_t) (frame_seq >> 32);
payload[4] = (uint8_t) (frame_seq >> 24);
payload[5] = (uint8_t) (frame_seq >> 16);
payload[6] = (uint8_t) (frame_seq >> 8);
payload[7] = (uint8_t) frame_seq;
memcpy(payload + 8U, encoded_pkt->data, (size_t) encoded_pkt->size);
memcpy(payload + 8U + (size_t) encoded_pkt->size, metadata, sizeof(*metadata));
rc = kcp_client_send_binary(sender->client, sender->target_peer, payload, payload_len);
if (rc != 0) {
return rc;
}
sender->next_frame_seq = frame_seq;
if (out_frame_seq != NULL) {
*out_frame_seq = frame_seq;
}
rc = video_sender_drain_pending_messages(sender);
return rc;
}
@@ -735,6 +754,109 @@ static void video_pipeline_note_backpressure(
pthread_mutex_unlock(&stats->mutex);
}
static void video_pipeline_note_capture_to_send(video_pipeline_stats_t *stats, uint32_t capture_to_send_ms) {
if (stats == NULL) {
return;
}
pthread_mutex_lock(&stats->mutex);
stats->last_capture_to_send_ms = capture_to_send_ms;
if (stats->avg_capture_to_send_ms <= 0.0) {
stats->avg_capture_to_send_ms = (double) capture_to_send_ms;
} else {
stats->avg_capture_to_send_ms = stats->avg_capture_to_send_ms * 0.9 + (double) capture_to_send_ms * 0.1;
}
pthread_mutex_unlock(&stats->mutex);
}
static int video_stage_logger_should_log(const video_stage_logger_t *logger, uint64_t frame_seq) {
if (logger == NULL || !logger->enabled) {
return 0;
}
if (logger->sample_mod <= 1U) {
return 1;
}
return frame_seq % logger->sample_mod == 0U;
}
static void video_stage_logger_log_frame(
video_stage_logger_t *logger,
uint64_t frame_seq,
double capture_ms,
double decode_ms,
double scale_ms,
double encode_ms,
double send_ms,
double pipeline_total_ms,
size_t jpeg_bytes,
uint64_t kcp_out_seg_delta,
uint32_t backlog_segments,
double window_pressure_pct,
int32_t video_srtt_ms
) {
char *line;
if (!video_stage_logger_should_log(logger, frame_seq)) {
return;
}
line = omni_strdup_printf(
"{\"ts_unix_nano\":%" PRId64 ",\"frame_seq\":%" PRIu64 ",\"capture_ms\":%.3f,\"decode_ms\":%.3f,\"scale_ms\":%.3f,\"encode_ms\":%.3f,\"send_ms\":%.3f,\"pipeline_total_ms\":%.3f,\"jpeg_bytes\":%zu,\"kcp_out_seg_delta\":%" PRIu64 ",\"backlog_segments\":%u,\"window_pressure_pct\":%.3f,\"video_srtt_ms\":%d}",
omni_now_unix_nano(),
frame_seq,
capture_ms,
decode_ms,
scale_ms,
encode_ms,
send_ms,
pipeline_total_ms,
jpeg_bytes,
kcp_out_seg_delta,
backlog_segments,
window_pressure_pct,
video_srtt_ms
);
if (line == NULL) {
return;
}
(void) omni_file_logger_write_line(&logger->file_logger, line);
free(line);
}
video_stage_logger_t *video_stage_logger_open_jsonl(const char *path, uint64_t sample_mod) {
video_stage_logger_t *logger;
FILE *file;
if (path == NULL || path[0] == '\0') {
return NULL;
}
if (omni_ensure_parent_dir(path) != 0) {
return NULL;
}
file = fopen(path, "ab");
if (file == NULL) {
return NULL;
}
logger = (video_stage_logger_t *) calloc(1, sizeof(*logger));
if (logger == NULL) {
fclose(file);
return NULL;
}
omni_file_logger_init_path(&logger->file_logger, file, path, 0);
logger->enabled = 1;
logger->sample_mod = sample_mod == 0U ? 1U : sample_mod;
return logger;
}
void video_stage_logger_close(video_stage_logger_t *logger) {
if (logger == NULL) {
return;
}
if (logger->file_logger.file != NULL) {
fclose(logger->file_logger.file);
}
omni_file_logger_destroy(&logger->file_logger);
free(logger);
}
static int video_server_error_requires_reconnect(const char *message) {
if (message == NULL || message[0] == '\0') {
return 0;
@@ -932,7 +1054,9 @@ int video_pipeline_run(const video_pipeline_config_t *config, video_pipeline_sta
AVFrame *scaled_frame = NULL;
AVPacket *encoded_pkt = NULL;
kcp_runtime_stats_t transport_stats;
kcp_runtime_stats_t transport_after_send;
int select_rc;
int should_log_stage = 0;
double total_start_ms = 0.0;
double capture_start_ms = 0.0;
double capture_end_ms = 0.0;
@@ -947,8 +1071,13 @@ int video_pipeline_run(const video_pipeline_config_t *config, video_pipeline_sta
video_pipeline_packet_metadata_t packet_metadata;
char reconnect_reason[256];
int frame_number = frame_index + 1;
uint64_t frame_seq = 0;
uint64_t out_segs_before_send = 0;
uint64_t out_segs_after_send = 0;
uint32_t capture_to_send_ms = 0;
memset(&transport_stats, 0, sizeof(transport_stats));
memset(&transport_after_send, 0, sizeof(transport_after_send));
memset(&packet_metadata, 0, sizeof(packet_metadata));
reconnect_reason[0] = '\0';
video_pipeline_report_progress(config);
@@ -956,9 +1085,7 @@ int video_pipeline_run(const video_pipeline_config_t *config, video_pipeline_sta
if (config->max_frames > 0 && frame_index >= config->max_frames) {
break;
}
if (config->enable_timing_logs) {
total_start_ms = video_pipeline_now_ms();
}
total_start_ms = video_pipeline_now_ms();
FD_ZERO(&fds);
FD_SET(fd, &fds);
@@ -972,9 +1099,7 @@ int video_pipeline_run(const video_pipeline_config_t *config, video_pipeline_sta
video_pipeline_set_errno_error(stats, "failed waiting for camera frame");
goto cleanup;
}
if (config->enable_timing_logs) {
capture_start_ms = video_pipeline_now_ms();
}
capture_start_ms = video_pipeline_now_ms();
memset(&buf, 0, sizeof(buf));
buf.type = V4L2_BUF_TYPE_VIDEO_CAPTURE;
@@ -983,10 +1108,8 @@ int video_pipeline_run(const video_pipeline_config_t *config, video_pipeline_sta
video_pipeline_set_errno_error(stats, "failed to dequeue V4L2 buffer");
goto cleanup;
}
if (config->enable_timing_logs) {
capture_end_ms = video_pipeline_now_ms();
decode_start_ms = capture_end_ms;
}
capture_end_ms = video_pipeline_now_ms();
decode_start_ms = capture_end_ms;
if (decode_mjpeg_frame(decoder, (const uint8_t *) buffers[buf.index].start, (int) buf.bytesused, &decoded_frame) != 0) {
if (config->enable_timing_logs) {
@@ -995,10 +1118,8 @@ int video_pipeline_run(const video_pipeline_config_t *config, video_pipeline_sta
(void) ioctl(fd, VIDIOC_QBUF, &buf);
continue;
}
if (config->enable_timing_logs) {
decode_end_ms = video_pipeline_now_ms();
scale_start_ms = decode_end_ms;
}
decode_end_ms = video_pipeline_now_ms();
scale_start_ms = decode_end_ms;
if (
ensure_scale_context(
&sws_ctx,
@@ -1018,10 +1139,8 @@ int video_pipeline_run(const video_pipeline_config_t *config, video_pipeline_sta
(void) ioctl(fd, VIDIOC_QBUF, &buf);
continue;
}
if (config->enable_timing_logs) {
scale_end_ms = video_pipeline_now_ms();
encode_start_ms = scale_end_ms;
}
scale_end_ms = video_pipeline_now_ms();
encode_start_ms = scale_end_ms;
if (encode_frame(encoder, scaled_frame, &encoded_pkt) != 0) {
if (config->enable_timing_logs) {
video_pipeline_print_timing_failure(frame_number, "encode");
@@ -1031,10 +1150,8 @@ int video_pipeline_run(const video_pipeline_config_t *config, video_pipeline_sta
(void) ioctl(fd, VIDIOC_QBUF, &buf);
continue;
}
if (config->enable_timing_logs) {
encode_end_ms = video_pipeline_now_ms();
send_start_ms = encode_end_ms;
}
encode_end_ms = video_pipeline_now_ms();
send_start_ms = encode_end_ms;
{
gps_video_sample_t gps_sample = get_latest_gps_for_video();
@@ -1186,7 +1303,13 @@ int video_pipeline_run(const video_pipeline_config_t *config, video_pipeline_sta
continue;
}
if (video_sender_send_packet(&sender, encoded_pkt, &packet_metadata) != 0) {
capture_to_send_ms = send_start_ms <= capture_start_ms
? 0U
: (uint32_t) (send_start_ms - capture_start_ms + 0.5);
packet_metadata.capture_to_send_ms = capture_to_send_ms;
out_segs_before_send = transport_stats.out_segs_total;
if (video_sender_send_packet(&sender, encoded_pkt, &packet_metadata, &frame_seq) != 0) {
pthread_mutex_lock(&stats->mutex);
stats->send_errors += 1;
pthread_mutex_unlock(&stats->mutex);
@@ -1200,19 +1323,43 @@ int video_pipeline_run(const video_pipeline_config_t *config, video_pipeline_sta
(void) ioctl(fd, VIDIOC_QBUF, &buf);
goto cleanup;
}
if (config->enable_timing_logs) {
send_end_ms = video_pipeline_now_ms();
send_end_ms = video_pipeline_now_ms();
should_log_stage = video_stage_logger_should_log(config->stage_logger, frame_seq);
if (should_log_stage) {
kcp_client_runtime_stats_snapshot(sender.client, &transport_after_send);
out_segs_after_send = transport_after_send.out_segs_total;
} else {
transport_after_send = transport_stats;
out_segs_after_send = out_segs_before_send;
}
video_pipeline_note_capture_to_send(stats, capture_to_send_ms);
pthread_mutex_lock(&stats->mutex);
stats->frames_sent += 1;
stats->bytes_sent += (uint64_t) encoded_pkt->size;
stats->last_frame_bytes = (uint64_t) encoded_pkt->size;
kcp_client_runtime_stats_snapshot(sender.client, &stats->transport);
stats->transport = transport_after_send;
pthread_mutex_unlock(&stats->mutex);
have_sent_frame = 1;
last_successful_send_ms = omni_now_millis32();
soft_drops_since_last_send = 0;
if (should_log_stage) {
video_stage_logger_log_frame(
config->stage_logger,
frame_seq,
capture_end_ms - capture_start_ms,
decode_end_ms - decode_start_ms,
scale_end_ms - scale_start_ms,
encode_end_ms - encode_start_ms,
send_end_ms - send_start_ms,
send_end_ms - total_start_ms,
(size_t) encoded_pkt->size,
out_segs_after_send >= out_segs_before_send ? out_segs_after_send - out_segs_before_send : 0U,
video_sender_backlog_segments(&transport_after_send),
transport_after_send.window_pressure_pct,
transport_after_send.srtt_ms
);
}
if (config->enable_timing_logs) {
video_pipeline_print_timing_row(
frame_number,