https://bugs.kde.org/show_bug.cgi?id=475205
--- Comment #6 from Benoît Tarrade <benoittarr...@hotmail.fr> ---
[And I cannot edit the later comment comment ... Damn it!]
So I was saying :
In `documentchecker.cpp::hasErrorInProject()` with my dataset :
```
// Note, I renamed some steps so that the function is easier to understand, you
know, usual stuff :-)
Starting project checking process - Playlist checks"
* 6 ms
"Validating document producers"
* 65s
Validating document chains
* 22s
Checking luma files
* 6.5ms
Checking for missing transitions
* 6.4 ms
Checking for missing filter assets
* 6.8 ms
Checking for missing effects
* 6.4 ms
```
So, while the overall time is around 1 and half minute and might probably be
shortened, that's not where the full 4 minutes of project loading are coming
alone.
There might be other stuff happening here and there, I'll continue looking but
there is something going on here.
Also, I think you very well know how to do it but I strongly advocate to have
this kind of instrumented code in the codebase :
```
#include <iostream>
#define DECL_STOPWATCH(varname) \
std::chrono::_V2::system_clock::time_point varname;
#define STOPWATCH_TIME_NOW(stopwatch) \
stopwatch = std::chrono::system_clock::now();
#define LOG_DURATION(start,end) \
/* Convert Nanoseconds to seconds */ \
std::cout << "elapsed time: " << (end-start).count() / 1000000000 << "s" <<
std::endl;
#define LOG(msg) \
std::cout << QFileInfo(__FILE__).baseName().toStdString() \
<< "::" << __func__ <<"():line" \
<< __LINE__ << ": " << msg << std::endl;
// And later in the code :
DECL_STOPWATCH(start);
DECL_STOPWATCH(end);
STOPWATCH_TIME_NOW(start);
LOG("Starting project checking process - Playlist checks");
// Some heavy process to be measured
// ...
// ...
STOPWATCH_TIME_NOW(end);
LOG_DURATION(start, end);
```
Note that this is a naive monothreaded implementation, multithreaded impl would
be a tad bit trickier, involving multithreaded logs in the loop, but the idea
remains the same.
And this can be easily be disabled on releases builds with a conditional macro
like this :
```
#ifdef PERF_MONITORING
#define DECL_STOPWATCH(varname) \
blahblahblah
// ... Other macros
#else
// Do nothing macro !
#define DECL_STOPWATCH(varname) ()
// Variables are not even declared, so this is transparent to the final code
#endif // End of PERF_MONITORING macros.
```
# About logging
[I have no lessons to give to anyone, I'm a software dev just like you and here
are a few personal thoughts about our common endeavour, I am not trying to rub
anyone the wrong way ^^ ]
There are tools here and there in kdenlive to perform some logging, albeit most
of the logs you see in the console is actually performed via qDebug.
I believe this is a hot topic in Kdenlive dev community (I can't see why it
wouldn't be!), it's probably due to a lack of resources and so much things to
work on already, pushing new features, etc...
However I believe having a proper logging system (and a bit enforced, be it
through macros to increase performances, or switches to enable/disable logging
systems if perfs are really an issue) is key for kdenlive stability.
In my opinion, Perf logging is really important, as well as error cases.
Logs should be filtered as well based on their criticality, etc...
In our software industry, we always welcome detailed logs that actually tells
you what's going on before you even open the codebase :)
--
You are receiving this mail because:
You are watching all bug changes.
