LogN is verry slow (Windows)

Aimless · 11-09-2017 12:39 PM

Log and LogN is really slow (on my pc like ~100 LogN / second). Is it normal behaviour or is it just my PC?

my benchmark:
0 logs per frame: 9000 fps
1 logs per frame: 80 fps
10 logs per frame: 9 fps

test code:

PHP Code:

int total = 0;

void InitPre()
{
   EE_INIT();
   D.mode(1024, 720);
}

bool Init()
{
   //LogConsole();
   D.sync(false);
   return true;
}
/******************************************************************************/
void Shut()
{
}
/******************************************************************************/
bool Update()
{
   if(Kb.bp(KB_ESC))return false;

   for(int i=0;  i<1;  ++i) LogN(S + total++);
  
   return true;
}
/******************************************************************************/

void Draw()
{
   D.clear(BLACK);
   D.text(Vec2(0, 0),  S+"Total: " + total);
   D.text(Vec2(0, -.1),  S+"fps: " + Time.fps());
}
/**********************************w********************************************/ 

Zervox · 11-09-2017 01:22 PM

Sounds normal enough to me, LogN writes to file at the same time as it is called if I remember correctly.

you have to remember you shouldn't measure LogN performance with FPS as it is writing to disk which means it is stalling the CPU for the file to end write operation(meaning most of the time is spent on the drive access).

Aimless · 11-09-2017 01:44 PM

yeah fps isn't the best measurement for this kind of problem but anyways simple:

PHP Code:

FileText file("log.txt");
   void log(const Str& str)
   {
         file.putText(str);
         file.putChar('\n');
         file.flush();
   } 

can push like 100`000 lines/second. Why does LogN can't even thousand. Or am i missing something? I mean databases write stuff and flush reliably all the time and they can process thousands of queries per second.

Zervox · 11-09-2017 01:45 PM

if you want to log whatever you are looping to get detailed stats to a file I would probably do something like

Str s;

s+= information you want logged + '\n';
s+= more information you want logged + '\n';
s+= more information you want logged + '\n';
Logn(S+s);

EDIT:
answer to your question, it is because FileText is buffering it in memory before writing everything in one go to my knowledge.
EDIT2:
I wonder if LogN doesn't reopen the log file everytime the function is called then sets position to end then appends the file for every call, unlike filetext which you have to do it specficially, making it faster to write to.

Aimless · 11-09-2017 02:34 PM

Yes, it seems that LogN reopens the file each time it writes - mystery solved! Thanks smile

~1000x improvement. LogN anyways falls noticably behind direct file writing, but thats acceptable and probably because of OutputDebugString etc.

quick & dirty fix (wont work if LogFile string is changed, not sure if it is allowed):

Code:

--- a/Engine/Source/Misc/Misc.cpp                                     

+++ b/Engine/Source/Misc/Misc.cpp                                     

@@ -552,9 +552,13 @@ void Log    (C Str &text)                        

    #endif                                                            

       // write to file log                                           

-      if(Is(LogFile))                                                

-      {                                                              

-         FileText f; if(f.append(LogFile))                           

+         if (Is(LogFile))                                            

+         {                                                           

+                static FileText f;                                   

+                static bool is_open = false;                         

+                if (!is_open)                                        

+                       is_open = f.append(LogFile);                  

+                if (is_open)                                         

          {

Zervox · 11-09-2017 02:45 PM

if you are unsure you probably should put this in the source section of the forum, although I doubt EE would go head over heels for this as it isn't exposing anything vital of the engine. smile

Edit: Also the code you posted is for the Log function not LogN but the code change applies all the same I guess as LogN only adds '\n' unless I am mistaken smile

Aimless · 11-09-2017 02:59 PM

oh, ok didn't notice that forum section. But anyways, nothing top secret there smile

And yes LogN is implemented on top of Log so it applies to both.

**Esenthel** · 11-09-2017 11:41 PM

Hi,
My tests, done in DEBUG mode:
0 logs per frame=300fps
1 logs per frame=200fps
2 logs per frame=160fps
10 logs per frame=60fps

I have an SSD, what about you?

Your modified "void Log (C Str &text)" does not call "f.flush" (internally called by file destructor) so you will not be able to see the results immediately, because they're buffered in RAM

If you want to do logging real-time, then I recommend dropping file/disk usage completely:
LogName(S); // disable disk usage
LogConsole(true); // open console for logging - Windows only
Also if you debug through Visual Studio, then you will see the output real-time in VS output window
So you will have VS output window + console output

Also: always avoid doing static variables inside function bodies, it costs performance - place them outside of the function.

Aimless · 11-12-2017 05:54 PM

No, my app was located on hard-drive which of course gives some slowdown. And yeah i forgot flush in the fixed version. Anyways I mean its not really serious issue, I just accidentally stumbled upon it and got confused grin

I am going to write my own logging routines anyway as I will need to write different files later on.
Thanks.

LogN is verry slow (Windows)
Author	Message