Logging

International board Development
#47

I still use it and not going to abandon 2010 until next version is fully functional :sunglasses:

#48

I really would like to restore old AI log style with teal colour. However, no matter what i try, it remains white. Any insight on this?

	"logging" : {
		"console" : {
			"colorMapping" : 
				{
					"color" : "magenta",
					"domain" : "network",
					"level" : "trace"
				},
				{
					"color" : "teal",
					"domain" : "ai",
					"level" : "trace"
				}
			],
			"threshold" : "debug"
		}
	}

Also, the old way with indents was much more readable. But that’s another issue.

#49

During AI profiling with GUI and FoW open I suprisingly discovered that destructor

CLoggerStream::~CLoggerStream

Takes almost 25% of execution time.

:open_mouth:

Most of it is call of CLogger::format including std::locale.

For AI running without GUI, the logs take over 50% of all execution time.

I believe some optimization here could be nice.

#50

Maybe it will be good to completely turn off logs. And have two exe-files - one for those who want to help debugging, and second - to just play.

#51

More work slowly if enabled module “Adventure AI trace”.
And yes, interesting looking vcmi.exe no logs.

#52

For Ivan - users.livejournal.com/_winnie/380215.html
I’m a bit lazy to google for english article about this, but in general I read several times that bare printf can be faster than iostream. With some tweaks though iostream can be practically the same speed as printf.

In SuperTuxKart a wrapper for printf is used. For more info you can have a look here, log.cpp/hpp: github.com/supertuxkart/stk-cod … /src/utils

#53

Uhm, not. The logs are not slowing down when they are printed out, but when they are generated internally. Neither console or hard disk have any impact on actual speed.

Not to mention there are tons of logs from entire engine and AI is only small fraction of them. Logs do not slow down AI only, they slow whole engine down!

#54

Were you checking the Debug or Release build?
Logging should not take that much time… unless we’re logging REALLY much.

What part of time is spend on the creating and setting locale? Perhaps we could just manually format the time.

Another way would be making logger asynchronous but that brings its own problems (eg. engine can crash and close without outputing all the logs).

#55

Release (RD), of course.

80-90% of the above. Rest of it is caused by boost::replace_all, we could probably use replace_first instead since log messages are trivial.

Still, I’m waiting for beegee to comment this situation.

#56

With latest trunk (just updated), things look like that:

GUI on, watching 2 AI players on XL map. Actually logging in total has higher CPU usage than the AI in total (>16%).

Logger profiling.png1082×809 26.8 KB

#57

Need details about CLogger::callTargets as it consume 22.7%

#58

Here you go, here’s part of call hierarchy

It seems that most expensive functions belong to MSVCP110 library :-/

Logger profiling2.png1318×858 34.2 KB

#59

What if f.e. cache dateStream inside CLogFormatter instance. Clear on each call but don`t reconstruct. This should prevent locale construction.

#60

Thanks for the detailed profiliing analysis. I improved logging performance a bit. Stingstream with locale/facet will be reused for logging operations. Additionally replace_first will be used instead of replace_all.

Warmonger, can you check if performance improved a little bit? According to your info most time is spent on logging to file (formatting that log message). Log file grows up to around 11 000 lines for just starting one map and one turn ingame with 2 AI players. IMO this isn’t that much, but if you play a few weeks ingame this can be too much.

#61

Improvement is dramatical, actually more than I expected. You can really feel it in game.

Logger profiling ok.png954×526 15.9 KB

#62

Try run map “The Mandate of Heaven” :smiley:

#63

Good to hear it! If performance is still a issue, just let me know:)

#64

I still would like to know WHY this bloody constructor was so slow?

#65

Sorry for late response :), try this:

"logging" : {
        "console" : {
            "colorMapping" : 
                {
                    "color" : "magenta",
                    "domain" : "network",
                    "level" : "trace"
                },
                {
                    "color" : "teal",
                    "domain" : "ai",
                    "level" : "debug"
                }
            ],
            "threshold" : "debug"
        }
    }

Threshold specifies maximum log level for console. Your trace messages with teal color weren’t logged at all. Set either level to debug in the color mapping or set threshold to trace (I wouldn’t suggest that, because then you will get a lot of noise).

#66

Thanks. However, the following is already included in “Adventure AI trace” mod in our repository :stuck_out_tongue: