>
> 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?
>
"Log" ?
> > > ---
> > > 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?
>
I used multiple time, both for checking data and for some replays with
timing (which is missing on the plain binary format)
> > > 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.
>
Usually parsers are updated and regular expressions get complicated.
Both not so much.
> 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.
>
It seems to me we need also to fix Qemu, spice-server, Gstreamer, Linux
Kernel, Glib and the list goes on and on.
If you refer to the fact that messages should be a bit more detailed
that "Sent", I agree but this is not related to log encapsulation
which is what this patch is attempting.
> 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...
>
I honestly don't want to spend weeks for the text on the log messages.
I would consider more follow ups for the current texts if you
consider them too short (and I agree).
> > > 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.
>
Engineering something specific for these statistics could be done,
the risks is spending quite some time for something less flexible,
harder to maintain and that maybe in a not so far future will
be not much useful.
A simple category/level for this as a log is less specific but
more flexible.
> 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.
>
As I said timed replays. I have a script that allows this.
Same the check internal data framing in specific codecs.
> 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 :)
>
For me looks like overengineering.
> > >
> > > 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.
>
Unless you use LTO is not up to the compiler and the linker cannot
do much. I don't think is important too, at least at the moment
and if gets important inline can be used.
> > > 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