logo logo

 Back to main page

The NWNX Community Forum

 FAQFAQ   SearchSearch   MemberlistMemberlist   UsergroupsUsergroups   RegisterRegister 
 ProfileProfile   Log in to check your private messagesLog in to check your private messages   Log inLog in 
 
How much time would you save

 
Post new topic   Reply to topic    nwnx.org Forum Index -> General Discussion
View previous topic :: View next topic  
Author Message
Baaleos



Joined: 02 Sep 2007
Posts: 830
PostPosted: Thu Oct 27, 2011 12:44    Post subject: How much time would you save Reply with quote
How much time, do you reckon, could potentially be saved if WriteTimestampedLogEntry and PrintString were turned off in your module?


In terms of Programming, IO operations are often seen as 'slow' operations.
Open Stream
Write
Close Stream

or Access an already open stream, and write etc.



Im just wondering has anyone profiled with and without timestamped log entries to see how much speed gain they get without the logs?

Would a server be alot faster without logs?
Back to top
View user's profile Send private message
Lokey



Joined: 02 Jan 2005
Posts: 158
PostPosted: Sun Oct 30, 2011 5:26    Post subject: Reply with quote
Logs are incredibly important though. Maybe a buffer ring then throw a bunch out at a time?

We do about 250kB worth of logging per hour with ~25 players on, and we only rotate the server log daily (gets to like 10MB or so)...while disk access stuff in nwn tends to be omigod slow, there's probably other areas like pathing and networking that would benefit a lot more--see skywing's stuff.
_________________
Neversummer PW NWNx powered mayhem Wink
Back to top
View user's profile Send private message
Asparius



Joined: 18 Sep 2007
Posts: 52
PostPosted: Thu Nov 10, 2011 17:20    Post subject: Reply with quote
As far as I know, WriteTimestampedLogEntry and PrintString aren't much time consuming . I had enabled logging of all kills on server, debug messages etc - about 200 MB per 24 hours - and turning logging off didn't really decrease server load.
MySQL access though can be really slow - so avoid, if possible, logging events in MySQL.
Back to top
View user's profile Send private message
Baaleos



Joined: 02 Sep 2007
Posts: 830
PostPosted: Thu Nov 17, 2011 13:25    Post subject: Reply with quote
Saying that mySQL is slow, is a relative comparison.

mySQL across the internet will obviously be slower than writing to a text file.
However, if mySQL server and module are on the same local machine, I would put forward that mySQL would be quicker.


Writing to a text file is a File I/O operation - which as proven by tests against mySQL, sqlLite, and NWNDB comparisons, are comparitively slower than mySQL and other database engines.

If you write something into notepad, and then click file-> save.
Your still talking perhaps a 100ms write time
Thats potentially 100ms of time that your nwscript is put on hold.
Multiply that by X amount (for each time you use WriteTimestampedLogEntry())

MySQL I believe was stated to have an average write time of between 20-60ms

I guess the way to test this would be to do


Code:

#include "aps_include" //Or whatever its called
void main()
{
int iNow = GetUnixTimeStamp();
int i;
for(i=0;i<=1000;i++)
   {
         WriteTimeStampedLogEntry(IntToString(i));
    }
int iNow2 = GetUnixTimeStamp();
int iTime = iNow2 - iNow;
float fAverage = IntToFloat(iTime)/1000.00;
}



Code:

#include "aps_include" //Or whatever its called
void main()
{
int iNow = GetUnixTimeStamp();
int i;
for(i=0;i<=1000;i++)
   {
         SetPersistentInt(GetModule(),"TEST_"+IntToString(i),1);
    }
int iNow2 = GetUnixTimeStamp();
int iTime = iNow2 - iNow;
float fAverage = IntToFloat(iTime)/1000.00;
}


Which one do you think will have the lowest time?
Back to top
View user's profile Send private message
Asparius



Joined: 18 Sep 2007
Posts: 52
PostPosted: Thu Nov 17, 2011 16:13    Post subject: Reply with quote
Baaleos: I'll bet that PrintString and WritetimestampedlogEntry will have time much lower than MySQL...

Checking in progress
Back to top
View user's profile Send private message
Baaleos



Joined: 02 Sep 2007
Posts: 830
PostPosted: Thu Nov 17, 2011 16:18    Post subject: Reply with quote
the second example should be scrapped

Since it actually performs 2 of 3 queries per an execution.


Better to change it to be

Code:

#include "aps_include" //Or whatever its called
void main()
{
int iNow = GetUnixTimeStamp();
int i;
for(i=0;i<=1000;i++)
   {
         string s = "insert into pwdata (tag) values ('"+IntToString(i)+"')";
         SQLExecDirect(s);
    }
int iNow2 = GetUnixTimeStamp();
int iTime = iNow2 - iNow;
float fAverage = IntToFloat(iTime)/1000.00;
}


This way, its 'closer' to a fair test.
The other example performs a select query first, then depending on the output of that, it then does an insert or update.
This one is a straight insert.

Back to top
View user's profile Send private message
Baaleos



Joined: 02 Sep 2007
Posts: 830
PostPosted: Thu Nov 17, 2011 16:21    Post subject: Reply with quote
Note -
My assumption that mySQL may be faster than WriteTimestampedLogEntry

comes from

the odbc speed comparison guide.


Database Write Read
SQLite (1) 30 ms 20 ms
SQLite (2) 36 ms 20 ms
SQLite (3) 2800 ms 20 ms
MySQL via ODBC 71 ms 38 ms
MySQL direct 68 ms 22 ms
Bioware DB (4) 856 ms 10 ms


Opening a text file, writing, closing a text file, would be in the same class as Bioware DB, maybe at a stretch SQLite.
Back to top
View user's profile Send private message
Asparius



Joined: 18 Sep 2007
Posts: 52
PostPosted: Thu Nov 17, 2011 16:24    Post subject: Reply with quote
50 strings 100 characters each:

MySQL: 5 miliseconds on MEMORY (!!!) engine.
PrintString : 2 miliseconds
WriteTimestampedLogEmtry : 2 miliseconds (slightly larger than PrintString)

Also, server log is NOT Bioware DB... Wink

Edit:

OnModuleLoad:
Code:

#include "aps_include"
#include "nwnx_time"

void main()
{
 //Setting the local variables for timer plugin on module, so access time will be fastest
 object oMod = GetModule();
 StartTimer (oMod, "PrintString");
 StartTimer (oMod, "WriteTimestampedLogEntry");
 StartTimer (oMod, "MySQL write");
 StopTimer (oMod, "PrintString");
 StopTimer (oMod, "WriteTimestampedLogEntry");
 StopTimer (oMod, "MySQL write");

 //Preparing MySQL table
 SQLInit();
 SQLExecDirect("CREATE TABLE IF NOT EXISTS test_log (entry VARCHAR(100)) Engine=InnoDB");

 int nIndex, nIndex2;
 string sAlpha = "abcdefghijklmnopqrstuvwxyz ";
 string sTemp;
 for (nIndex = 0; nIndex < 50; nIndex++)
    {
     sTemp = "";
     for (nIndex2 = 0; nIndex2 < 100; nIndex2++)
        {
         sTemp = sTemp + GetSubString (sAlpha, Random(26), 1);
        }
     SetLocalString (oMod, "STRTEST_" + IntToString (nIndex), sTemp);
     PrintString(sTemp);
    }

 DelayCommand (5.0, ExecuteScript ("test_sql", oMod));
 DelayCommand (10.0, ExecuteScript ("test_writetim", oMod));
 DelayCommand (15.0, ExecuteScript ("test_printstring", oMod));
}



test_sql:
Code:

#include "aps_include"
#include "nwnx_time"


void main()
{
 object oMod = GetModule();
 int nIndex;


 StartTimer (oMod, "MySQL write");

    for (nIndex = 0; nIndex < 50; nIndex++)
        SQLExecDirect ("INSERT INTO test_log VALUES ('" + GetLocalString (oMod, "STRTEST_" + IntToString (nIndex)) + "')");

 StopTimer (oMod, "MySQL write");
}


test_printstring:
Code:

#include "aps_include"
#include "nwnx_time"


void main()
{
 object oMod = GetModule();
 int nIndex;
 StartTimer(oMod, "PrintString");



 for (nIndex = 0; nIndex < 50; nIndex++)
     PrintString (GetLocalString (oMod, "STRTEST_" + IntToString (nIndex)));

 StopTimer (oMod, "PrintString");
}


test_writetim
Code:

#include "aps_include"
#include "nwnx_time"


void main()
{
 object oMod = GetModule();
 int nIndex;


 StartTimer (oMod, "WriteTimestampedLogEntry");

 for (nIndex = 0; nIndex < 50; nIndex++)
     WriteTimestampedLogEntry (GetLocalString (oMod, "STRTEST_" + IntToString (nIndex)));

 StopTimer (oMod, "WriteTimestampedLogEntry");

}


Result from nwnx_time:

Code:

o Performance counter frequency: 2500020000 (1/s)
o Starting timer on PrintString0
o Starting timer on WriteTimestampedLogEntry0
o Starting timer on MySQL write0
o Stopping timer on PrintString0, elapsed: 62 µs / 0.062 msec / 0.000 sec
o Stopping timer on WriteTimestampedLogEntry0, elapsed: 68 µs / 0.068 msec / 0.000 sec
o Stopping timer on MySQL write0, elapsed: 77 µs / 0.077 msec / 0.000 sec
o Starting timer on MySQL write0
o Stopping timer on MySQL write0, elapsed: 25624 µs / 25.624 msec / 0.026 sec
o Starting timer on WriteTimestampedLogEntry0
o Stopping timer on WriteTimestampedLogEntry0, elapsed: 1967 µs / 1.967 msec / 0.002 sec
o Starting timer on PrintString0
o Stopping timer on PrintString0, elapsed: 1774 µs / 1.774 msec / 0.002 sec


Last edited by Asparius on Thu Nov 17, 2011 16:30; edited 2 times in total
Back to top
View user's profile Send private message
Baaleos



Joined: 02 Sep 2007
Posts: 830
PostPosted: Thu Nov 17, 2011 16:26    Post subject: Reply with quote
50 strings is not really large enough to draw substantial conclusions from.

The speed comparison for nwnx odbc was done with 500 writes.


Ideally I would use 1000

Also - can you show the code your executing.

If your doing SetPersistentInt or string, then that is performing twice as much as PrintString/WriteTimeStampedLogEntry.

Last edited by Baaleos on Thu Nov 17, 2011 16:31; edited 1 time in total
Back to top
View user's profile Send private message
Asparius



Joined: 18 Sep 2007
Posts: 52
PostPosted: Thu Nov 17, 2011 16:30    Post subject: Reply with quote
Please check the system I have used to measure the speed. Also, on InnoDB engine MySQL was over 10 times slower than PrintString...

By the way - the difference becomes even greater with single writes - every access to MySQL takes at least 5 miliseconds (edit: actually, 3 ms), PrintString - < 200 microseconds (assuming the hard disk has write cache)

PS. All tests ran on Windows XP and MySQL 4.1 (newer versions are slower...)

Last edited by Asparius on Thu Nov 17, 2011 17:20; edited 1 time in total
Back to top
View user's profile Send private message
Baaleos



Joined: 02 Sep 2007
Posts: 830
PostPosted: Thu Nov 17, 2011 16:35    Post subject: Reply with quote
where is your database?

I can tell you now, that write time for mySQL is crap.

25 Seconds to write 50 strings - Yeah, if its on the moon?! (correction - I see now that it is milliseconds)

I've managed to write hundreds of 2da strings to a database within 30 seconds when the database was local

Last edited by Baaleos on Thu Nov 17, 2011 16:40; edited 1 time in total
Back to top
View user's profile Send private message
Asparius



Joined: 18 Sep 2007
Posts: 52
PostPosted: Thu Nov 17, 2011 16:37    Post subject: Reply with quote
I have my database on the same machine that nwserver is.

Results for 1000 strings write:

Code:

o Starting timer on MySQL write0
o Stopping timer on MySQL write0, elapsed: 438426 µs / 438.426 msec / 0.438 sec
o Starting timer on WriteTimestampedLogEntry0
o Stopping timer on WriteTimestampedLogEntry0, elapsed: 36750 µs / 36.750 msec / 0.037 sec
o Starting timer on PrintString0
o Stopping timer on PrintString0, elapsed: 35066 µs / 35.066 msec / 0.035 sec


So, MySQL has about 2000 strings per second, compared to > 25000 strings per second in PrintString... I will try other db engines as well.

Edit: Archive engine is quite faster:

Code:

o Starting timer on MySQL write0
o Stopping timer on MySQL write0, elapsed: 107982 µs / 107.982 msec / 0.108 sec
o Starting timer on WriteTimestampedLogEntry0
o Stopping timer on WriteTimestampedLogEntry0, elapsed: 37655 µs / 37.655 msec / 0.038 sec
o Starting timer on PrintString0
o Stopping timer on PrintString0, elapsed: 35775 µs / 35.775 msec / 0.036 sec


Still 3 times slower though than PrintString...

PS. Also, on Windows machine, nwserverlog is always opened by nwserver process .

PPS. Single string write on Archive engine = 3 milisec vs 60 microsec PrintString...
Back to top
View user's profile Send private message
Display posts from previous:   
Post new topic   Reply to topic    nwnx.org Forum Index -> General Discussion All times are GMT + 2 Hours
Page 1 of 1

 
Jump to:  
You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot vote in polls in this forum


Powered by phpBB © 2001, 2005 phpBB Group