View previous topic :: View next topic |
Author |
Message |
Baaleos
Joined: 02 Sep 2007 Posts: 830
|
Posted: Thu Oct 27, 2011 12:44 Post subject: How much time would you save |
|
|
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 |
|
|
Lokey
Joined: 02 Jan 2005 Posts: 158
|
Posted: Sun Oct 30, 2011 5:26 Post subject: |
|
|
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 |
|
Back to top |
|
|
Asparius
Joined: 18 Sep 2007 Posts: 52
|
Posted: Thu Nov 10, 2011 17:20 Post subject: |
|
|
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 |
|
|
Baaleos
Joined: 02 Sep 2007 Posts: 830
|
Posted: Thu Nov 17, 2011 13:25 Post subject: |
|
|
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 |
|
|
Asparius
Joined: 18 Sep 2007 Posts: 52
|
Posted: Thu Nov 17, 2011 16:13 Post subject: |
|
|
Baaleos: I'll bet that PrintString and WritetimestampedlogEntry will have time much lower than MySQL...
Checking in progress |
|
Back to top |
|
|
Baaleos
Joined: 02 Sep 2007 Posts: 830
|
Posted: Thu Nov 17, 2011 16:18 Post subject: |
|
|
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 |
|
|
Baaleos
Joined: 02 Sep 2007 Posts: 830
|
Posted: Thu Nov 17, 2011 16:21 Post subject: |
|
|
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 |
|
|
Asparius
Joined: 18 Sep 2007 Posts: 52
|
Posted: Thu Nov 17, 2011 16:24 Post subject: |
|
|
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...
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 |
|
|
Baaleos
Joined: 02 Sep 2007 Posts: 830
|
Posted: Thu Nov 17, 2011 16:26 Post subject: |
|
|
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 |
|
|
Asparius
Joined: 18 Sep 2007 Posts: 52
|
Posted: Thu Nov 17, 2011 16:30 Post subject: |
|
|
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 |
|
|
Baaleos
Joined: 02 Sep 2007 Posts: 830
|
Posted: Thu Nov 17, 2011 16:35 Post subject: |
|
|
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 |
|
|
Asparius
Joined: 18 Sep 2007 Posts: 52
|
Posted: Thu Nov 17, 2011 16:37 Post subject: |
|
|
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 |
|
|
|
|
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
|