Instrumented to observe timing of execution

`gprof` did not yield insights of sufficient detail.
This commit is contained in:
Frank Leon Rose 2020-01-27 15:11:04 -05:00
parent 575e6b0a42
commit 173dc8a3fb
7 changed files with 65 additions and 2 deletions

View file

@ -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);

View file

@ -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,

View file

@ -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:

View file

@ -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;
}

View file

@ -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) {

View file

@ -14,16 +14,35 @@
#include <limits.h>
#include <signal.h>
#include <stdlib.h>
#include <sys/gmon.h>
#include <sys/time.h>
#include <sys/types.h>
#include <sys/wait.h>
#include <unistd.h>
#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]);

View file

@ -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 <time.h>
uint64_t get_timestamp();
void log_timestamp(const char *tag);
#endif