vsg::logging functionality

[Robert Osfield]

Hi All,

Resolving an issue with the Android build Gareth has to add AndroidLogLib to deal with the __android_log_print() usage that was originally used to workaround Android sending all cout and cerr messages to /dev/null.  Rather than just added these new dependency to the core VSG for just a bit of debug output used in a single file I've decided to do a quick experiment with adding some logging functionality to the VSG.

My first step in this experiment has to been to create a Logging branch of vsgExamples:

   https://github.com/vsg-dev/vsgExamples/tree/logging

This also inspired a previous suggestion from Sam Brkopac for having such functionality in the core VSG during the discussion about VulkanSceneGraph-1.0 work.  Sam has used spdlog in his own projects so suggested that as possible reference.  The LOC count for spdlog is half the size of the whole VSG project which is pretty crazy, so I'm not about to pull it into core VSG.

My vsglog.cpp example is just 168 lines of code, and already has a base Logger class, a thread safe StdLogger implementation that directs to std::cout and std::cerr, and CustomLogger implementation.  Usage looks like:

    vsg::info("info string");
    vsg::warn("warn string");
    vsg::critical("critical string");
    vsg::error("error string");

    vsg::info("time ", 10, "ms, vector = (", vsg::vec3(10.0f, 20.0f, 30.0f), ")");

    vsg::log() = CustomLogger::create();

    vsg::info("info string");
    vsg::warn("warn string");
    vsg::critical("critical string");
    vsg::error("error string");
    vsg::error("here ", std::string("and"), " matrix  = {",vsg::dmat4{}, "}");

Output from this is:

$ vsglog  
cout: info string
cout: warn string
cerr: critical string
cerr: error string
cout: info : time 10ms, vector = (10 20 30)
custom cout: info string
custom cout: warn string
custom cerr: critical string
custom cerr: error string
custom cout: error : here and matrix  = {
   1 0 0 0
   0 1 0 0
   0 0 1 0
   0 0 0 1
}

The lines in form of:

    vsg::info("time ", 10, "ms, vector = (", vsg::vec3(10.0f, 20.0f, 30.0f), ")");

Are handled by a template that uses a std::ostringstream that is created and destroyed on each invocation of the template function, so while it's super flexible it's far from efficient.  

I will have a think whether I can reuse a ostringstream implementation per thread to avoid creating an destroying the ostringstream objects. Stuff like this will make the code rather more complicated...

I could just go with really basic and inefficient solution for 1.0, then come back to it.  The question now me is how much functionality to build in right now.   I'm open to suggestions about how to tackle this/what you'd like to see.

Cheers,

Robert.

[Robert Osfield]

Hi All,

I have spent the day trying out different API combinations and done benchmarking to help decide what approach to go with.  My aim is to provide basic logging facilities that are thread safe, easy to extend and enough basic features to be used out of the box. The aim isn't to provide the most feature rich or high performing logging functionality, it's very much about getting the most bang for our buck w.r.t new code.

I am now happy enough to create a logging branch of the VulkanSceneGraph and have added an include/vsg/io/Logger.h and src/vsg/io/Logger.cpp files to provide the basic functionality.   VSG and vsgExample branches:

    https://github.com/vsg-dev/VulkanSceneGraph/tree/logging

    https://github.com/vsg-dev/vsgExamples/tree/logging

The Logger header that contains the base vsg::Logger class, an vsg::StdLogger and vsg::NullLogger implementation, and vsg::debug(..), vsg::info(..), vsg::warn(...), vsg::error() message functions. The header and source files are:

   https://github.com/vsg-dev/VulkanSceneGraph/blob/logging/include/vsg/io/Logger.h

   https://github.com/vsg-dev/VulkanSceneGraph/blob/logging/src/vsg/io/Logger.cpp

The example is:

   https://github.com/vsg-dev/vsgExamples/blob/logging/examples/io/vsglog/vsglog.cpp

The example is bit messy at this point as it's functioned as a test of the API/implementation and for benchmark rather than as teaching example.  Once the functionality is more mature I'll clean this up a bit more.

My next step is to replace all the std::cout/std::cerr usage in VSG, vsgXchange etc with the new vsg::debug(..), vsg::info() etc. API.

Cheers,

Robert.

[Sam Brkopac]

Hey Robert,

I like the way this is developing. One thing that I think would be worth considering is some ability to group VSG logs together.

Sometimes I’d like to just see the output of the database pager or the reader writers. In OSG enabling certain loggers give me a lot of info I don’t require. Layered on top of that a cmake option to completely disable those code paths would be nice.

Thanks, Sam

On Jun 21, 2022, at 12:43 PM, Robert Osfield <robert....@gmail.com> wrote:



--
You received this message because you are subscribed to the Google Groups "vsg-users : VulkanSceneGraph Developer Discussion Group" group.
To unsubscribe from this group and stop receiving emails from it, send an email to vsg-users+...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/vsg-users/a534324d-3a42-4247-a8a0-af1239032fd6n%40googlegroups.com.

[Robert Osfield]

Hi Sam,

On Tue, 21 Jun 2022 at 19:31, Sam Brkopac <brk...@gmail.com> wrote:

I like the way this is developing. One thing that I think would be worth considering is some ability to group VSG logs together.

Sometimes I’d like to just see the output of the database pager or the reader writers. In OSG enabling certain loggers give me a lot of info I don’t require. Layered on top of that a cmake option to completely disable those code paths would be nice.

It's possible right now to locally create a Logger and call it directly, rather than via the vsg::info(..) etc. functions which map to the vsg::logger() singleton's Logger.

   vsg::info("information"); // calls vsg::logger()->info(message);

   auto my_logger = MyLogger::create();

   my_logger->infor("my local information");

Another approach I was wondering about was to have a FilePerThreadLogger class that you assign a file to write to for each thread, then in the FilPerThreadLogger::info_implementation() method it maps the thread id to container/file to write the information to.

You could also put timing information into each call within a custom Logger as well.

Essentially there are lots of ways you could customize things to do interesting things, however, I'm mindful that it could easily be another big sink of my time and another delay to getting VSG-1.0 finally out the door.  What precipitation this work is addressing an issue with Android just sending all std::cout/std::cerr to /dev/null,  the new vsg::Logger class is a step towards addressing this in a cross platform way that will enable Android applications to handle this type of output in a graceful way.

My focus now will be changing the VSG code base across to the use of the vsg::info()/vsg::warning()/vsg::error() message handling, once that's done and everything looks to be working I'll merge with master.

After that I think the focus would then turn to members of the community trying it out, seeing if they can customize things to suit their usage cases.  It might be that some of this work will inform revisions of the vsg::Logger functionality, and if there is useful functionality that can be shared then this could either go into vsglog as an example for others or even potentially rolled into the core VSG.

Cheers,

Robert.

[Robert Osfield]

While taking our dog out for his evening walk it occurred to me that users could write a custom Logger class that implements Loger::error_implementation() etc. that throw exceptions rather than print out a message.  This ErrorThrowExceptionLogger class could be used when debugging applications make it easier to pin point code that reports errors.   This would allow code to have graceful error handling with a printed message in normal operation without serious failure, but when debugging developers could be forced to resolve them.  One might just choose to always throw and exception in such code, but this approach would give you options.

[Robert Osfield]

Hi All,

The github automated builds picked up some issues on the Windows DLL build, these took a bit of experimenting to figure out what the compiler was having issue with.  I have resolved these and the build of the loging branch is now building cleanly on Linux, macOS and Windows.

Cheers,

Robert/

[Robert Osfield]

To help adapt existing debug/report(std::ostream&) functions that the VSG has to work with the new vsg::Logger capability I have introduced a functor based methods that reuses the Logger's ostringstream, these are implemented in form:

        using PrintToStreamFunction = std::function<void(std::ostream&)>;

        /// thread safe access to stream for writing debug output.
        void debug_stream(PrintToStreamFunction print)
        {
            if (level > DEBUG) return;

            std::scoped_lock<std::mutex> lock(_mutex);
            _stream.str({});
            _stream.clear();

            print(_stream);

            debug_implementation(_stream.str());
        }

Usage is in form (from VulkanSceneGraph/src/vsg/nodes/PagedLOD.cpp:

     debug_stream([&](std::ostream& fout) { check(); print(fout); });

The original code this replaces was:

     check(); print(std::cout);

So the new code is more complicated, but it does provide a number of useful capabilities over the original code:

1. The obvious one is that you can override the default Logger and direct the debug output to wherever you want. 
2. The check(); print(fout) called is now only called if the Logger::level allows DEBUG output, this makes the CPU overhead very low when they are disabled
3. It adapts to stream output even when the underlying Logger implementation doesn't use C++ io/storage.
4. Thread safe IO/access.
   

--

Something I'm considering is a compile switch to map the debug()/debug_stream() to inline {} implementations to enable the compiler to avoid generating any code for use of debug message functions for applications that don't require them.  I'm on fence on this as it adds a bit more complexity to CMake and the headers.

Thoughts?

[Robert Osfield]

Earlier I wrote about the new debug/info_stream() functor API in the form

    info_stream([&](std::ostream& fout) { report(fout); });

After writing that email it occurred to me that modern pragmas can infer the parameter type so auto& should be possible so I tried:

    info_stream([&](auto& fout) { report(fout); });

And it compiles on all the compilers tested on github automated build.  While replacing std::ostream& with auto& isn't a big simplification it's reduces the syntactic glue code that wraps the bit that is of real interest - the code within the lambda function.

--

I'm now about 70% through converting all the VSG std::cout/std::cerr code across to using the new vsg::Logger API.  I'm pretty happy with how this work is progress - the new code is a bit cleaner and expresses better the intent more clearly i.e. this is just a debug message, general information, or this is a warning/error which really shouldn't be headed. 

I haven't come across any road blocks so far so I think once I've done the purge of std::cout/cerr code from the core VSG and associated libs I think we should be good to merge with master.  There are potentially additions that we might dream up for the new vsg::Logger functionality, but for the VulkanSceneGraph-1.0 I think the current API/Implementation is sufficient so any of these additions would be nice to have rather than MUST HAVE for the release.

As I'm getting close to being at a point where I can merge with master community testing of the logging branch would be helpful.  I've created logging branches of vsgXchange, vsgGIS, vsgImGui, vsgQt and vsgExamples.

Cheers,

Robert.

[Robert Osfield]

To help with testing, and to provide an easier way of changing the vsg::Logger::level I've added the following to the vsgviewer example:

   if (int log_level = 0; arguments.read("--log-level", log_level)) vsg::Logger::instance()->level = vsg::Logger::Level(log_level);

To set the level of message to print out all messages, including debug messages:

    vsgviewer models/openstreetmap.vsgt --log-level 0

If you just leave the default of 2 then you'll only see LOGGER_INFO and above, which for this model you'll see no output in normal circumstances.

I'm considering adding a vsg::FileLogger that can redirect all the output to a file.  I'm also wondering if we should have a prefix option iike "debug: ", "info: " etc, though perhaps this is something we can just leave to end users own custom vsg::Logger.  I'm really wary of keeping adding lots of different features though as users are likely to all have their own preferred way to log messages, I could easily see myself chasing niche usage cases if I start down the road of introducing too much functionality - easy extensibility would be my preferred way to go about things.

So for 1.0 I'm thinking what will all users need at a minimum, and how to do make it easy for them to add their own message/log handling so this minimum feature set isn't limiting.

Cheers,

Robert.

[Robert Osfield]

I have now completed cout/cerr replacements with the new vsg::debug(..)/info(..)/wanr(..)/error(..) functions, so this is all now checked into the logging branch of the VSG.

Tomorrow I'll go through the other libraries and vsgExamples to see if any further replacements are required.

I now feel that the logging branch is in good enough state to merge with VSG master, so if there aren't any issues flagged by the community I'll do that tomorrow, so please have a look over this work and chip in your questions/impressions/suggestions.

Cheers,

Robert.

[Robert Osfield]

Hi All,

This morning I decided to add:vsg::log(Logger::Level msg_level, ...)  API to the existing vsg::info(..) etc. to enable applications to decide what level they intend messages to use at runtime, usage of the log function looks like:

    vsg::log(vsg::Logger::LOGGER_DEBUG, std::string("string log debug"));
    vsg::log(vsg::Logger::LOGGER_DEBUG, "cstring log debug");
    vsg::log(vsg::Logger::LOGGER_INFO, "log info");
    vsg::log(vsg::Logger::LOGGER_WARN, "log warn");
    vsg::log(vsg::Logger::LOGGER_ERROR, "log error");

When testing this new functionality I spotted issues with other parts of the API and implementation that wasn't functioning as intended.  To resolve these issues I had to try a number of different interface/implementation combinations to coax C++ into doing what I intended.  As part of this I also added use of std::string_view to provide a bit more efficient way of passing c strings to the Logger without the need to create a std::string for string literals.

Now that the API has been rounded out and shaken down I've cleaned up the vsglog example, and generated a PR for this logging branch.  I'll leave it till tomorrow morning before I merge this.

   https://github.com/vsg-dev/VulkanSceneGraph/pull/462

The vsglog example is:

   https://github.com/vsg-dev/vsgExamples/blob/logging/examples/io/vsglog/vsglog.cpp

You all have another chance to get testing, if everything looks clean I'll merge with VSG master tomorrow :-)

[Robert Osfield]

HI All,

I found out that our Internet connection was down this morning and it didn't come back online until 10pm this evening...  So I'm a bit slow with merged changes I've done today, but these are now checked in.

The main addition I made today was a new vsglog_mt example that tested out a custom ThreadLogger with a multi-threaded test case.  This custom logger ended up neat and tidy enough to warrant merging with the core VSG.  The new vsg::ThreadLogger class prints out the thread id as a prefix to all debug/info/warn/error(..) message calls, and allows users to map a thread id to a string prefix.  The changes that add vsg::ThreadLogger are:

    https://github.com/vsg-dev/VulkanSceneGraph/commit/4a6ee6bd155d004d9c4a5998ad998fe0f81221b3

The new vsglog_mt example illustrates how to set up threads using vsg::OperationThreads, how to assign names for the main and std::threads created by OperationThreads, then adds Operations that write out messages from the different threads.  The example is checked into the vsgExamples logging branch:

    https://github.com/vsg-dev/vsgExamples/blob/logging/examples/io/vsglog_mt/vsglog_mt.cpp

This is all done in 74 lines of code.  You can run the example with arguments:

    vsglog_mt

And you'll see output like:

main | info: set thread prefix for thread::id = 140697078003264 to thread 0 |  
main | info: set thread prefix for thread::id = 140697069610560 to thread 1 |  
main | info: set thread prefix for thread::id = 140697061217856 to thread 2 |  
main | info: set thread prefix for thread::id = 140697052825152 to thread 3 |  
main | info: set thread prefix for thread::id = 140697044432448 to thread 4 |  
main | info: set thread prefix for thread::id = 140697036039744 to thread 5 |  
main | info: set thread prefix for thread::id = 140697027647040 to thread 6 |  
main | info: set thread prefix for thread::id = 140697019254336 to thread 7 |  
main | info: set thread prefix for thread::id = 140697010861632 to thread 8 |  
main | info: set thread prefix for thread::id = 140697002468928 to thread 9 |  
main | info: set thread prefix for thread::id = 140696994076224 to thread 10 |  
main | info: set thread prefix for thread::id = 140696985683520 to thread 11 |  
main | info: set thread prefix for thread::id = 140696977290816 to thread 12 |  
main | info: set thread prefix for thread::id = 140696968898112 to thread 13 |  
main | info: set thread prefix for thread::id = 140696960505408 to thread 14 |  
main | info: set thread prefix for thread::id = 140696952112704 to thread 15 |  
main | info: Adding 100 MyOperations.
thread 7 | info: info() operation 0
thread 7 | debug: log() operation 0
thread 3 | info: info() operation 1

...

...

read 3 | info: info() operation 39
thread 3 | ERROR: log() operation 39
thread 12 | debug: log() operation 32
thread 7 | info: info() operation 46
thread 7 | Warning: log() operation 46
main | info: Finished processing operations.
thread 10 | info: log() operation 33
thread 13 | info: info() operation 59
thread 13 | ERROR: log() operation 59
thread 0 | info: info() operation 60
thread 0 | debug: log() operation 60
main | info: OperationThreads destroyed.

--

The fact that is was straightforward to implement vsg::ThreadLogger and this multi-threaded example is a good sign that the API is in the right ballpark for what we need for 1.0.  It blows the OSG notification system out of the water, so might be another feature we want to back-port to the OSG at some later date.

I was planning to merge with master today but as I've only just got back online and the codebase has new additions I'll leave the logging branch open for testing for another night.  If no issue arise I'll merge over the weekend.

Cheers,

Robet.

[Robert Osfield]

Hi All,

Today I completed my testing and code reviews and have merged the various logging branches with their respective masters.  Users should be able to just update to latest master for VSG, vsgGIS, vsgQt, vsgXchange, vsgExamples and have everything run as before with their own applications save for a few differences in the way that VSG generated console messages will look - they'll have a debug: info: warn: or error: prefix now.

You may see compile errors in your own applications if you use std::cout/std::cerr in your own code and relied upon VSG headers including <iostream>, to fix the build in these cases just add a #include <iostream> or convert the code across to use vsg::info(..) etc.

For those curious about how much code was required for the new Logger classes/functions - it's a total of 590 lines of code.

$ wc include/vsg/io/Logger.h src/vsg/io/Logger.cpp  
 343  1121 12367 include/vsg/io/Logger.h
 247   607  6339 src/vsg/io/Logger.cpp
 590  1728 18706 total

The is a bit bigger than the OSG's osg::Notify support, but it's far easier to extend, it's fully thread safe and has a logger that is specifically helpful for threaded applications.

$ wc include/osg/Notify src/osg/Notify.cpp  
 145   698  5271 include/osg/Notify
 258   610  7470 src/osg/Notify.cpp
 403  1308 12741 total

While a bit bigger than the OSG's system, it's 2.3% the size of spdlog's headers which weigh in at 25568 lines of code.  Sure spdlog has more functionality, but as many applications were able to get by osg::Notify for 2 decades, me thinks vsg::Logger should be good enough for VulkanSceneGraph-1.0.

And yes, it should be possible to write a custom vsg::Logger to redirect to spdlog or other logging facilities if you really must have additional functionality.

Cheers,

Robert.

[Robert Osfield]

I just write a vsg::log() message and out of curiosity decided to try out the __FILE__, __LINE_ and __func__ built in macros and these worked fine, but in checking online came across  _PRETTY_FUNCTION (gcc only) and then C++20 feature std::source_location, which can potentially be used for logging implementations.  There a mention of it in this StackOverflow thread:

    https://stackoverflow.com/questions/4384765/whats-the-difference-between-pretty-function-function-func

While it's not something I going to put in the VSG it's nice to know that these things are available.