On Thu, 2018-06-14 at 04:42 -0400, Frediano Ziglio wrote:
> >
> > The FrameLog class provides RAII for the FILE and encapsulates the
> > logging functionality.
> >
> > Signed-off-by: Lukáš Hrázký <lhrazky@xxxxxxxxxx>
>
> Why "FrameLog" if, as you said too, is managing two types of logs?
Because I couldn't come up with a name that better describes something
doing two things at once :) What do you prefer? Split it or suggest a
better name?
> > ---
> > While I retained all the behaviour of the original implementation, I
> > don't like it as it is.
> >
> > 1. The class is doing two different things:
> > a) logging the binary frames for later replay
> > b) writing a time-stamped log for diagnostics
> >
>
> You can have both outputs on the same file.
Is that actually useful in any way? What is the hex format of the
frames useful for?
> > 2. The time-stamped diagnostics lines seem quite rudimentary, like
> > some short helper messages I put in my code when debugging a problem.
> > Doesn't look like something we'd want to release, god forbid we'd have
> > to keep the log format backwards compatible in the future :)
> >
>
> I don't think nobody is planning to have is backward compatible and as
> far as I know this is common for logging. Probably for the same reasoning
> you should remove logging from 70% of the applications...
Not entirely, since I expect people to have scripts that parse the log.
So if someone wants to change the messages, he will break your parser.
I'm not saying we need to guarantee the format here, but I'm saying
there are reasons not to change it. And they aren't too well defined,
as well as the actual format is in majority not well defined and just
something that spuriously came into existence over time.
So I guess what I'm asking is should we actually stop and think of what
we want it to look like in a released product...
> > However, I don't know how the frame log is used (I guess it's mostly
> > Frediano who uses it?), so I didn't try to improve it, as I don't really
> > know how. I'd like to:
> >
>
> Uri used the full binary to replay as videos.
> I use for statistics like frame average in bytes or average time to
> process a frame and such things.
I do see the need for the measurements, though, as I hope I already
expressed, the log seems kind of arbitrary to me. But I can't think of
a better way.
I'm not sure what the binary log to replay videos is useful for, though
(apart from some possible early testing which may not be relevant
anymore). Uri, do you still find it useful for something?
> > a) either get some input on how to improve it - address the two mentioned
> > issues, or (much rather)
> >
>
> Issues?? As said looks like issues of probably 70% applications of the world.
Yes, issues, and no, you can't compare this to a debug log.
> > b) merge this separation and have someone post a followup that cleans it
> > up.
> >
>
> Cleans what?
Both of the issues :P (I don't think we need to play with words here...
if you disagree with me, just say so ;))
> Looks like you are suggesting to handle binary file and
> other logs as completely separate thing. I don't see this as a cleanup,
> more a split.
Yeah, a split is one of the solutions. As I said, I don't entirely know
what is the log used for. If you told me, for example, that you need
the hex frame dumps alongside the timestamped information, a split
would not be possible.
I suggest we first remove what is not useful (if anything) and then,
based on the requirements, come up with a cleaner design. Should not be
hard in this case :)
> >
> > src/Makefile.am | 2 +
> > src/frame-log.cpp | 76 +++++++++++++++++++++++++++++++++++
> > src/frame-log.hpp | 39 ++++++++++++++++++
> > src/spice-streaming-agent.cpp | 71 ++++++++------------------------
> > 4 files changed, 134 insertions(+), 54 deletions(-)
> > create mode 100644 src/frame-log.cpp
> > create mode 100644 src/frame-log.hpp
> >
> > diff --git a/src/Makefile.am b/src/Makefile.am
> > index 18ed22c..fead680 100644
> > --- a/src/Makefile.am
> > +++ b/src/Makefile.am
> > @@ -54,6 +54,8 @@ spice_streaming_agent_SOURCES = \
> > concrete-agent.hpp \
> > error.cpp \
> > error.hpp \
> > + frame-log.cpp \
> > + frame-log.hpp \
> > mjpeg-fallback.cpp \
> > mjpeg-fallback.hpp \
> > jpeg.cpp \
> > diff --git a/src/frame-log.cpp b/src/frame-log.cpp
> > new file mode 100644
> > index 0000000..b0bd09e
> > --- /dev/null
> > +++ b/src/frame-log.cpp
> > @@ -0,0 +1,76 @@
> > +/* A utility logger for logging frames and/or time information.
> > + *
> > + * \copyright
> > + * Copyright 2018 Red Hat Inc. All rights reserved.
>
> When you move code you have to retain the original copyright
> (in this case would be 2016-2018 as the rest is the same).
Right, I'll fix it.
> > + */
> > +
> > +#include "frame-log.hpp"
> > +
> > +#include "error.hpp"
> > +#include "hexdump.h"
> > +
> > +#include <cstdarg>
> > +#include <string.h>
> > +#include <sys/time.h>
> > +
> > +
> > +namespace spice {
> > +namespace streaming_agent {
> > +
> > +FrameLog::FrameLog(const char *log_name, bool log_binary, bool log_frames) :
> > + log_binary(log_binary),
> > + log_frames(log_frames)
> > +{
> > + if (log_name) {
> > + log_file = fopen(log_name, "wb");
> > + if (!log_file) {
> > + throw Error(std::string("Failed to open log file '") + log_name
> > + "': " + strerror(errno));
> > + }
> > + if (!log_binary) {
> > + setlinebuf(log_file);
> > + }
> > + }
> > +}
> > +
> > +FrameLog::~FrameLog()
> > +{
> > + if (log_file) {
> > + fclose(log_file);
> > + }
> > +}
> > +
> > +void FrameLog::log_stat(const char* format, ...)
> > +{
> > + if (log_file && !log_binary) {
> > + fprintf(log_file, "%" PRIu64 ": ", get_time());
> > + va_list ap;
> > + va_start(ap, format);
> > + vfprintf(log_file, format, ap);
> > + va_end(ap);
> > + fputs("\n", log_file);
> > + }
> > +}
> > +
> > +void FrameLog::log_frame(const void* buffer, size_t buffer_size)
> > +{
> > + if (log_file) {
> > + if (log_binary) {
> > + fwrite(buffer, buffer_size, 1, log_file);
> > + } else if (log_frames) {
> > + hexdump(buffer, buffer_size, log_file);
> > + }
> > + }
> > +}
> > +
> > +/**
> > + * Returns current time in microseconds.
> > + */
> > +uint64_t FrameLog::get_time()
> > +{
> > + struct timeval now;
> > + gettimeofday(&now, NULL);
> > +
> > + return (uint64_t)now.tv_sec * 1000000 + (uint64_t)now.tv_usec;
> > +}
> > +
> > +}} // namespace spice::streaming_agent
> > diff --git a/src/frame-log.hpp b/src/frame-log.hpp
> > new file mode 100644
> > index 0000000..2ebe01b
> > --- /dev/null
> > +++ b/src/frame-log.hpp
> > @@ -0,0 +1,39 @@
> > +/* A utility logger for logging frames and/or time information.
> > + *
> > + * \copyright
> > + * Copyright 2018 Red Hat Inc. All rights reserved.
> > + */
> > +
> > +#ifndef SPICE_STREAMING_AGENT_FRAME_LOG_HPP
> > +#define SPICE_STREAMING_AGENT_FRAME_LOG_HPP
> > +
> > +#include <cinttypes>
> > +#include <stddef.h>
> > +#include <stdio.h>
> > +
> > +
> > +namespace spice {
> > +namespace streaming_agent {
> > +
> > +class FrameLog {
> > +public:
> > + FrameLog(const char *log_name, bool log_binary, bool log_frames);
> > + FrameLog(const FrameLog &) = delete;
> > + FrameLog &operator=(const FrameLog &) = delete;
> > + ~FrameLog();
> > +
> > + __attribute__ ((format (printf, 2, 3)))
> > + void log_stat(const char* format, ...);
> > + void log_frame(const void* buffer, size_t buffer_size);
> > +
> > + static uint64_t get_time();
> > +
> > +private:
> > + FILE *log_file = NULL;
>
> nullptr?
Will do.
> > + bool log_binary = false;
> > + bool log_frames = false;
> > +};
> > +
> > +}} // namespace spice::streaming_agent
> > +
> > +#endif // SPICE_STREAMING_AGENT_FRAME_LOG_HPP
> > diff --git a/src/spice-streaming-agent.cpp b/src/spice-streaming-agent.cpp
> > index 1121f35..aef49c7 100644
> > --- a/src/spice-streaming-agent.cpp
> > +++ b/src/spice-streaming-agent.cpp
> > @@ -5,8 +5,8 @@
> > */
> >
> > #include "concrete-agent.hpp"
> > -#include "hexdump.h"
> > #include "mjpeg-fallback.hpp"
> > +#include "frame-log.hpp"
> > #include "stream-port.hpp"
> > #include "error.hpp"
> >
> > @@ -57,8 +57,6 @@ struct SpiceStreamDataMessage
> >
> > static bool streaming_requested = false;
> > static bool quit_requested = false;
> > -static bool log_binary = false;
> > -static bool log_frames = false;
> > static std::set<SpiceVideoCodecType> client_codecs;
> >
> > static bool have_something_to_read(StreamPort &stream_port, bool blocking)
> > @@ -221,17 +219,6 @@ static void spice_stream_send_frame(StreamPort
> > &stream_port, const void *buf, co
> > syslog(LOG_DEBUG, "Sent a frame of size %u\n", size);
> > }
> >
> > -/* returns current time in micro-seconds */
> > -static uint64_t get_time(void)
> > -{
> > - struct timeval now;
> > -
> > - gettimeofday(&now, NULL);
> > -
> > - return (uint64_t)now.tv_sec * 1000000 + (uint64_t)now.tv_usec;
> > -
> > -}
> > -
> > static void handle_interrupt(int intr)
> > {
> > syslog(LOG_INFO, "Got signal %d, exiting", intr);
> > @@ -330,14 +317,8 @@ static void cursor_changes(StreamPort *stream_port,
> > Display *display, int event_
> > }
> > }
> >
> > -#define STAT_LOG(format, ...) do { \
> > - if (f_log && !log_binary) { \
> > - fprintf(f_log, "%" PRIu64 ": " format "\n", get_time(), ##
> > __VA_ARGS__); \
> > - } \
> > -} while(0)
> > -
>
> This could have performance impact. Don't think is a problem with
> the current code.
Yeah. You mean an additional function call? I also don't think it's
important here... Could inline the function, but in this case I'd just
leave it up to the compiler.
> > static void
> > -do_capture(StreamPort &stream_port, FILE *f_log)
> > +do_capture(StreamPort &stream_port, FrameLog &frame_log)
> > {
> > unsigned int frame_count = 0;
> > while (!quit_requested) {
> > @@ -361,13 +342,13 @@ do_capture(StreamPort &stream_port, FILE *f_log)
> > if (++frame_count % 100 == 0) {
> > syslog(LOG_DEBUG, "SENT %d frames\n", frame_count);
> > }
> > - uint64_t time_before = get_time();
> > + uint64_t time_before = FrameLog::get_time();
> >
> > - STAT_LOG("Capturing...");
> > + frame_log.log_stat("Capturing...");
> > FrameInfo frame = capture->CaptureFrame();
> > - STAT_LOG("Captured");
> > + frame_log.log_stat("Captured");
> >
> > - uint64_t time_after = get_time();
> > + uint64_t time_after = FrameLog::get_time();
> > syslog(LOG_DEBUG,
> > "got a frame -- size is %zu (%" PRIu64 " ms) "
> > "(%" PRIu64 " ms from last frame)(%" PRIu64 " us)\n",
> > @@ -385,18 +366,12 @@ do_capture(StreamPort &stream_port, FILE *f_log)
> > codec = capture->VideoCodecType();
> >
> > syslog(LOG_DEBUG, "wXh %uX%u codec=%u\n", width, height,
> > codec);
> > - STAT_LOG("Started new stream wXh %uX%u codec=%u", width,
> > height, codec);
> > + frame_log.log_stat("Started new stream wXh %uX%u codec=%u",
> > width, height, codec);
> >
> > spice_stream_send_format(stream_port, width, height, codec);
> > }
> > - STAT_LOG("Frame of %zu bytes:", frame.buffer_size);
> > - if (f_log) {
> > - if (log_binary) {
> > - fwrite(frame.buffer, frame.buffer_size, 1, f_log);
> > - } else if (log_frames) {
> > - hexdump(frame.buffer, frame.buffer_size, f_log);
> > - }
> > - }
> > + frame_log.log_stat("Frame of %zu bytes:", frame.buffer_size);
> > + frame_log.log_frame(frame.buffer, frame.buffer_size);
> >
> > try {
> > spice_stream_send_frame(stream_port, frame.buffer,
> > frame.buffer_size);
> > @@ -404,7 +379,7 @@ do_capture(StreamPort &stream_port, FILE *f_log)
> > syslog(e);
> > break;
> > }
> > - STAT_LOG("Sent");
> > + frame_log.log_stat("Sent");
> >
> > read_command(stream_port, false);
> > }
> > @@ -418,6 +393,8 @@ int main(int argc, char* argv[])
> > const char *stream_port_name =
> > "/dev/virtio-ports/org.spice-space.stream.0";
> > int opt;
> > const char *log_filename = NULL;
> > + bool log_binary = false;
> > + bool log_frames = false;
> > int logmask = LOG_UPTO(LOG_WARNING);
> > const char *pluginsdir = PLUGINSDIR;
> > enum {
> > @@ -493,20 +470,10 @@ int main(int argc, char* argv[])
> >
> > register_interrupts();
> >
> > - FILE *f_log = NULL;
> > - if (log_filename) {
> > - f_log = fopen(log_filename, "wb");
> > - if (!f_log) {
> > - syslog(LOG_ERR, "Failed to open log file '%s': %s\n",
> > - log_filename, strerror(errno));
> > - return EXIT_FAILURE;
> > - }
> > - if (!log_binary) {
> > - setlinebuf(f_log);
> > - }
> > - for (const std::string& arg: old_args) {
> > - STAT_LOG("Args: %s", arg.c_str());
> > - }
> > + FrameLog frame_log(log_filename, log_binary, log_frames);
> > +
> > + for (const std::string& arg: old_args) {
> > + frame_log.log_stat("Args: %s", arg.c_str());
> > }
> > old_args.clear();
> >
> > @@ -531,17 +498,13 @@ int main(int argc, char* argv[])
> > std::thread cursor_th(cursor_changes, &stream_port, display,
> > event_base);
> > cursor_th.detach();
> >
> > - do_capture(stream_port, f_log);
> > + do_capture(stream_port, frame_log);
> > }
> > catch (std::exception &err) {
> > syslog(LOG_ERR, "%s\n", err.what());
> > ret = EXIT_FAILURE;
> > }
> >
> > - if (f_log) {
> > - fclose(f_log);
> > - f_log = NULL;
> > - }
> > closelog();
> > return ret;
> > }
>
> Frediano
_______________________________________________
Spice-devel mailing list
Spice-devel@xxxxxxxxxxxxxxxxxxxxx
https://lists.freedesktop.org/mailman/listinfo/spice-devel