diff --git a/app/src/capture.c b/app/src/capture.c index 8e2ea40d..4d02bc6b 100644 --- a/app/src/capture.c +++ b/app/src/capture.c @@ -81,6 +81,7 @@ static void notify_complete() { static bool in_frame_to_png( AVIOContext *output_context, AVCodecContext *codecCtx, AVFrame *inframe) { + uint64_t start = get_timestamp(); int targetHeight = codecCtx->height; int targetWidth = codecCtx->width; struct SwsContext * swCtx = sws_getContext(codecCtx->width, @@ -102,6 +103,8 @@ static bool in_frame_to_png( swCtx, inframe->data, inframe->linesize, 0, inframe->height, rgbFrame->data, rgbFrame->linesize); + LOGV("Scaling image: %llu", get_timestamp() - start); + AVCodec *outCodec = avcodec_find_encoder(AV_CODEC_ID_PNG); if (!outCodec) { LOGE("Failed to find PNG codec"); @@ -122,7 +125,7 @@ static bool in_frame_to_png( outCodecCtx->time_base.den = codecCtx->time_base.den; } else { outCodecCtx->time_base.num = 1; - outCodecCtx->time_base.den = 30; // FPS + outCodecCtx->time_base.den = 10; // FPS } int ret = avcodec_open2(outCodecCtx, outCodec, NULL); @@ -145,11 +148,14 @@ static bool in_frame_to_png( ret = avcodec_receive_packet(outCodecCtx, &outPacket); avcodec_close(outCodecCtx); av_free(outCodecCtx); + LOGV("Converted to PNG: %llu", get_timestamp() - start); if (ret >= 0) { // Dump packet avio_write(output_context, outPacket.data, outPacket.size); notify_complete(); av_packet_unref(&outPacket); + LOGV("Wrote file: %llu", get_timestamp() - start); + log_timestamp("Capture written"); return true; } else { LOGE("Failed to receive packet"); @@ -267,6 +273,9 @@ void capture_destroy(struct capture *capture) { } static bool capture_process(struct capture *capture, const AVPacket *packet) { + log_timestamp("Processing packet"); + static uint64_t total = 0; + uint64_t start = get_timestamp(); if (capture->finished) { LOGV("Skipping redundant call to capture_push"); } else { @@ -276,6 +285,9 @@ static bool capture_process(struct capture *capture, const AVPacket *packet) { capture->finished = found_png; } } + uint64_t duration = get_timestamp() - start; + total += duration; + LOGV("Capture step microseconds: %llu total: %llu", duration, total); return capture->finished; } @@ -305,6 +317,7 @@ capture_packet_delete(struct capture_packet *rec) { static int run_capture(void *data) { + log_timestamp("Running capture thread"); struct capture *capture = data; for (;;) { @@ -341,6 +354,7 @@ run_capture(void *data) { bool capture_start(struct capture *capture) { + log_timestamp("Starting capture thread"); capture->thread = SDL_CreateThread(run_capture, "capture", capture); if (!capture->thread) { @@ -366,6 +380,7 @@ capture_join(struct capture *capture) { bool capture_push(struct capture *capture, const AVPacket *packet) { + log_timestamp("Received packet"); mutex_lock(capture->mutex); assert(!capture->stopped); diff --git a/app/src/main.c b/app/src/main.c index 5aea485d..5daa68f9 100644 --- a/app/src/main.c +++ b/app/src/main.c @@ -45,6 +45,7 @@ main(int argc, char *argv[]) { #ifndef NDEBUG SDL_LogSetAllPriority(SDL_LOG_PRIORITY_DEBUG); #endif + SDL_LogSetAllPriority(SDL_LOG_PRIORITY_VERBOSE); struct scrcpy_cli_args args = { .opts = SCRCPY_OPTIONS_DEFAULT, diff --git a/app/src/scrcpy.c b/app/src/scrcpy.c index 6fe2965a..4563f295 100644 --- a/app/src/scrcpy.c +++ b/app/src/scrcpy.c @@ -282,6 +282,8 @@ av_log_callback(void *avcl, int level, const char *fmt, va_list vl) { bool scrcpy(const struct scrcpy_options *options) { + log_timestamp("scrcpy Started"); + bool captures = !!options->capture_filename; bool record = !!options->record_filename; struct server_params params = { @@ -315,10 +317,12 @@ scrcpy(const struct scrcpy_options *options) { bool controller_initialized = false; bool controller_started = false; + log_timestamp("sdl_init_and_configure"); if (!sdl_init_and_configure(options->display)) { goto end; } + log_timestamp("server_connect_to"); if (!server_connect_to(&server)) { goto end; } @@ -329,12 +333,14 @@ scrcpy(const struct scrcpy_options *options) { // screenrecord does not send frames when the screen content does not // change therefore, we transmit the screen size before the video stream, // to be able to init the window immediately + log_timestamp("device_read_info"); if (!device_read_info(server.video_socket, device_name, &frame_size)) { goto end; } struct decoder *dec = NULL; if (options->display) { + log_timestamp("Display and fps_counter_init"); if (!fps_counter_init(&fps_counter)) { goto end; } @@ -380,6 +386,7 @@ scrcpy(const struct scrcpy_options *options) { capture_initialized = true; } + log_timestamp("stream_init"); av_log_set_callback(av_log_callback); stream_init(&stream, server.video_socket, dec, rec, cap); @@ -437,9 +444,12 @@ scrcpy(const struct scrcpy_options *options) { input_manager.prefer_text = options->prefer_text; + log_timestamp("Starting event_loop"); ret = event_loop(options->display, options->control); + log_timestamp("Terminated event_loop"); LOGD("quit..."); + log_timestamp("stream_init"); screen_destroy(&screen); end: diff --git a/app/src/server.c b/app/src/server.c index ff167aeb..2c9bbbd9 100644 --- a/app/src/server.c +++ b/app/src/server.c @@ -121,6 +121,7 @@ disable_tunnel(struct server *server) { static process_t execute_server(struct server *server, const struct server_params *params) { + log_timestamp("Starting device server"); char max_size_string[6]; char bit_rate_string[11]; char max_fps_string[6]; @@ -158,6 +159,7 @@ execute_server(struct server *server, const struct server_params *params) { // Port: 5005 // Then click on "Debug" #endif + LOGV("Executing ADB command"); return adb_execute(server->serial, cmd, sizeof(cmd) / sizeof(cmd[0])); } @@ -231,11 +233,13 @@ server_start(struct server *server, const char *serial, } if (!push_server(serial)) { + LOGE("Failed to push server to device."); SDL_free(server->serial); return false; } if (!enable_tunnel(server)) { + LOGE("Failed to enable tunnel."); SDL_free(server->serial); return false; } @@ -259,6 +263,7 @@ server_start(struct server *server, const char *serial, } } + LOGV("Executing server"); // server will connect to our server socket server->process = execute_server(server, params); @@ -278,12 +283,15 @@ server_start(struct server *server, const char *serial, bool server_connect_to(struct server *server) { + log_timestamp("Starting server_connect_to"); if (!server->tunnel_forward) { + log_timestamp("Accepting video socket"); server->video_socket = net_accept(server->server_socket); if (server->video_socket == INVALID_SOCKET) { return false; } + log_timestamp("Accepting control socket"); server->control_socket = net_accept(server->server_socket); if (server->control_socket == INVALID_SOCKET) { // the video_socket will be cleaned up on destroy @@ -295,6 +303,7 @@ server_connect_to(struct server *server) { } else { uint32_t attempts = 100; uint32_t delay = 100; // ms + log_timestamp("Connecting video socket"); server->video_socket = connect_to_server(server->local_port, attempts, delay); if (server->video_socket == INVALID_SOCKET) { @@ -302,6 +311,7 @@ server_connect_to(struct server *server) { } // we know that the device is listening, we don't need several attempts + log_timestamp("Connecting control socket"); server->control_socket = net_connect(IPV4_LOCALHOST, server->local_port); if (server->control_socket == INVALID_SOCKET) { @@ -313,6 +323,7 @@ server_connect_to(struct server *server) { disable_tunnel(server); // ignore failure server->tunnel_enabled = false; + log_timestamp("Finished server_connect_to"); return true; } diff --git a/app/src/stream.c b/app/src/stream.c index 974bcf52..6770cbc5 100644 --- a/app/src/stream.c +++ b/app/src/stream.c @@ -60,6 +60,8 @@ stream_recv_packet(struct stream *stream, AVPacket *packet) { packet->pts = pts != NO_PTS ? (int64_t) pts : AV_NOPTS_VALUE; + log_timestamp("Received packet via socket stream"); + return true; } @@ -308,7 +310,7 @@ stream_init(struct stream *stream, socket_t socket, bool stream_start(struct stream *stream) { - LOGD("Starting stream thread"); + log_timestamp("Starting stream thread"); stream->thread = SDL_CreateThread(run_stream, "stream", stream); if (!stream->thread) { diff --git a/app/src/sys/unix/command.c b/app/src/sys/unix/command.c index fbcf2355..a3a62d21 100644 --- a/app/src/sys/unix/command.c +++ b/app/src/sys/unix/command.c @@ -14,16 +14,35 @@ #include #include #include +#include +#include #include #include #include #include "util/log.h" +uint64_t get_timestamp() { + struct timeval tv; + gettimeofday(&tv,NULL); + return tv.tv_sec*(uint64_t)1000000+tv.tv_usec; +} + +static uint64_t StartTime = 0; +void log_timestamp(const char *tag) { + uint64_t now = get_timestamp(); + if (StartTime==0) { + StartTime = now; + } + LOGV("Timestamp: %llu ms %s", (now-StartTime) / 1000, tag); +} + enum process_result cmd_execute(const char *const argv[], pid_t *pid) { int fd[2]; + uint64_t start = get_timestamp(); + if (pipe(fd) == -1) { perror("pipe"); return PROCESS_ERROR_GENERIC; @@ -31,6 +50,7 @@ cmd_execute(const char *const argv[], pid_t *pid) { enum process_result ret = PROCESS_SUCCESS; + log_timestamp("Running command"); *pid = fork(); if (*pid == -1) { perror("fork"); @@ -48,6 +68,7 @@ cmd_execute(const char *const argv[], pid_t *pid) { ret = PROCESS_ERROR_GENERIC; goto end; } + LOGV("Command microseconds: %s %llu ms", argv[0], (get_timestamp()-start)/1000); } else if (*pid == 0) { // child close read side close(fd[0]); diff --git a/app/src/util/log.h b/app/src/util/log.h index 5955c7fb..eaacf949 100644 --- a/app/src/util/log.h +++ b/app/src/util/log.h @@ -10,4 +10,7 @@ #define LOGE(...) SDL_LogError(SDL_LOG_CATEGORY_APPLICATION, __VA_ARGS__) #define LOGC(...) SDL_LogCritical(SDL_LOG_CATEGORY_APPLICATION, __VA_ARGS__) +#include +uint64_t get_timestamp(); +void log_timestamp(const char *tag); #endif