On Thu, 2018-06-14 at 06:44 -0400, Frediano Ziglio wrote:
> >
> > 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" ?
I'm not sure that's funny :P
Since it is not a generic log, on the contrary, it is quite specific in
the multiple things it's doing, "Log" is not really a good 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?
> >
>
> I used multiple time, both for checking data and for some replays with
> timing (which is missing on the plain binary format)
Allright, fair enough.
> > > > 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.
Yeah...
> > 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 don't think we're going to do that. So far the only time spent was
this discussion (which could have been shorter too) and any subsequent
patches surely are in the order of hours at most (I don't want to
design anything complex here either).
> I would consider more follow ups for the current texts if you
> consider them too short (and I agree).
Yes, that's the least we should do.
> > > > 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 tend to agree with that.
> > 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.
Ok, but that still doesn't require the time-stamped event messages be
in the same log as the frame data. So potentially a split into a frame
dump log and timing analysis log would make sense? But I take it you
prefer it to be together?
> > 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.
No, overengineering is making a design unnecessarily complex for given
requirements. This is the step before that, actually defining the
requirements so that you can approach the design the right way :) In
this simple case, this process should take about ~5 minutes to a person
familiar with all the use-cases...
FWIW, seems we both think we're spending more than the necessary time
on this discussion, but I don't think we should just drop the issue for
"not being worth it" just because of our inability to have an efficient
discussion :)
>From my POV, you seem to disagree with my points or don't understand
them, but you don't make your standpoint clear, so it takes several
email exchanges for me to find out what it actually is.
> > > >
> > > > 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