| View previous topic :: View next topic |
| Author |
Message |
virusman
Joined: 30 Jan 2005
Posts: 1020
Location: Russia
|
 Posted: Mon May 19, 2008 13:12 Post subject: |
 |
|
| Disco wrote: | Thanks! The BioWare one is nice, but I do prefer the NWNX version!
Would it be an idea to let the profiler show the last script executed as well, so you can take a look at your last profiler update when NWN crashes? The
[Script Options]
Enable Logging=1
option provided by BioWare is quite nice but it logs every function used and you can imagine how that affects log file size. |
Well.. when the server crashes, it crashes. The OS terminates the process giving no chance for Profiler to write anything to the log. |
|
| Back to top |
|
 |
Skywing
Joined: 03 Jan 2008
Posts: 321
|
| Posted: Mon May 19, 2008 13:36 Post subject: |
|
|
I had some code to log the last received packets when a crash occurred in NWN2. The way I did this was to make a memory-mapped ring buffer file which I'd write data out to as packets came in.
This way, if the server process crashed, the data would already be scheduled to be committed the disk file by the OS, irrespective of whether the process survived or not. (I'm not sure what the rules for this are on Linux, but on Windows, once you've made the write to the memory mapping, it will either be immediately committed or committed by a kernel worker thread later as per caching. This happens regardless of whether the process survives to "cleanly" clean up it's references to the memory mapped file or is killed "hard" due to a crash. As long as the process doesn't scribble garbage over the memory map before going down, the data should be intact.)
I should think that the same principle could be applied here for logging function calls in a space-economical and crash-resilient fashion, if desired.
- S |
|
| Back to top |
|
|
virusman
Joined: 30 Jan 2005
Posts: 1020
Location: Russia
|
| Posted: Mon May 19, 2008 14:16 Post subject: |
|
|
| I had to do fflush() on every write in Linux, otherwise the changes don't appear in the log if the server crashes. |
|
| Back to top |
|
|
Disco
Joined: 06 Dec 2006
Posts: 152
|
| Posted: Mon May 19, 2008 15:52 Post subject: |
|
|
A crashed server doesn't necessarily mean a crashed NWNX/plugin, right? I have no clue how the profiler is working but I assumed it pools the number of scripts ran and flushes the formatted info once in a while. I guess you can ignore my suggestion if that's not the case.  |
|
| Back to top |
|
|
Skywing
Joined: 03 Jan 2008
Posts: 321
|
| Posted: Mon May 19, 2008 16:24 Post subject: |
|
|
The plugins run in the context of the nwserver process.
virusman: What file I/O routines were you using? I would expect that if you used fprintf/fwrite. If you use the write syscall directly, or you're writing to pages backed by an mmap'd file, I would expect that as soon as the call returns, or the write to the page completes, that you are guaranteed that the data will (eventually) be written to disk (assuming the box doesn't go down). In particular, I would expect that even if the process dies, the data will still be written from the cache at some point.
fprintf/fwrite do buffering in user mode, as I recall, and obviously that will not end well if the process dies prematurely and there's still data in the C runtime's stream I/O buffer that has not yet been written out to disk yet.
(Don't know for certain that this is the case in POSIX/Linux, but it is in Windows. I would be fairly surprised if it's not the case in Linux, though.) |
|
| Back to top |
|
|
virusman
Joined: 30 Jan 2005
Posts: 1020
Location: Russia
|
| Posted: Mon May 19, 2008 17:26 Post subject: |
|
|
| Skywing wrote: | The plugins run in the context of the nwserver process.
virusman: What file I/O routines were you using? I would expect that if you used fprintf/fwrite. If you use the write syscall directly, or you're writing to pages backed by an mmap'd file, I would expect that as soon as the call returns, or the write to the page completes, that you are guaranteed that the data will (eventually) be written to disk (assuming the box doesn't go down). In particular, I would expect that even if the process dies, the data will still be written from the cache at some point.
fprintf/fwrite do buffering in user mode, as I recall, and obviously that will not end well if the process dies prematurely and there's still data in the C runtime's stream I/O buffer that has not yet been written out to disk yet.
(Don't know for certain that this is the case in POSIX/Linux, but it is in Windows. I would be fairly surprised if it's not the case in Linux, though.) |
Yes, you're absolutely right. But how do I write just the last script call/packet/etc. without writing them all to the log? |
|
| Back to top |
|
|
Skywing
Joined: 03 Jan 2008
Posts: 321
|
| Posted: Mon May 19, 2008 17:36 Post subject: |
|
|
Well, like I said, the way I did it for my packet logging patch for nwnx4 was to have a ring buffer file that was memory mapped and had space for N fixed-size records for the events that you wanted to record.
In my case, the file was a binary file described as an array of these structs:
| Code: | #define MAX_LOGGED_PACKET_LENGTH ( 4096 )
typedef struct _LOGGED_PACKET
{
ULONG Length;
FILETIME RecvTime;
ULONG ActualPacketLength;
ULONG PacketLength;
UCHAR PacketData[ MAX_LOGGED_PACKET_LENGTH ];
} LOGGED_PACKET, * PLOGGED_PACKET;
#define MAX_LOGGED_PACKETS ( 128 ) |
Saving a packet to the log just involved copying the packet data into the slot in the ring buffer (modulo MAX_LOGGED_PACKETS):
| Code: |
void
WritePacketToLog(
__in const void *PacketData,
__in unsigned long Length
)
{
PLOGGED_PACKET Packet;
if (!g_LogPacketView)
return;
//
// No synchronization is necessary as packets are always handled in the main thread.
//
Packet = &g_LogPacketView[ g_LogPacketIndex ];
g_LogPacketIndex = (g_LogPacketIndex + 1) % MAX_LOGGED_PACKETS;
//
// Write packet attributes out to the section view mapping.
//
GetSystemTimeAsFileTime( &Packet->RecvTime );
Packet->ActualPacketLength = Length;
if (Length > MAX_LOGGED_PACKET_LENGTH)
Length = MAX_LOGGED_PACKET_LENGTH;
Packet->PacketLength = Length;
//
// Write the packet data to the buffer. Note that we truncate packets if
// they were too large. We record the original length and the truncated
// length so that we can determine this fact.
//
memcpy( Packet->PacketData, PacketData, Length );
} |
You could do the same with a text file format if you space-padded each record or something like that to keep them fixed size, I suppose (or something more complicated if you really wanted to support variable length records), although keep in mind that without something to reparse things in the correct order, the "start" of the log may be in the middle of the log file due to the circular logging mechanism.
In this case, g_LogPacketView is a pointer to the base of the memory mapped file, and g_LogPacketIndex is the current insertion index (default to zero at init time, increment for every packet, wrap to zero after reaching maximum).
Displaying the log entries in order is a simple matter of organizing by timestamp and not entry order in the file. |
|
| Back to top |
|
|
virusman
Joined: 30 Jan 2005
Posts: 1020
Location: Russia
|
|
| Back to top |
|
|
jeffdavis_99
Joined: 17 Apr 2007
Posts: 4
Location: USA
|
| Posted: Tue May 20, 2008 3:08 Post subject: |
|
|
Sweet, now we just need to poke nwnx-chat! 
_________________
jeffdavis_99
Nukingstreet Icewind Dales |
|
| Back to top |
|
|
Disco
Joined: 06 Dec 2006
Posts: 152
|
| Posted: Tue May 20, 2008 10:47 Post subject: |
|
|
Does this one work with 1.68 as well? I'd like to test it but there's an irate woman abusing my PC/NWN at the moment so I can't install 1.69. |
|
| Back to top |
|
|
virusman
Joined: 30 Jan 2005
Posts: 1020
Location: Russia
|
| Posted: Tue May 20, 2008 15:40 Post subject: |
|
|
| Disco wrote: |
Does this one work with 1.68 as well? I'd like to test it but there's an irate woman abusing my PC/NWN at the moment so I can't install 1.69. |
No.
1.60 and 1.61 are the same, just 1.60 is for NWN <=1.68, 1.61 is for NWN 1.69. |
|
| Back to top |
|
|
virusman
Joined: 30 Jan 2005
Posts: 1020
Location: Russia
|
|
| Back to top |
|
|
jeffdavis_99
Joined: 17 Apr 2007
Posts: 4
Location: USA
|
| Posted: Tue May 20, 2008 19:51 Post subject: |
|
|
By bad, you're awesome, thanks.
I get some strange characters instead of script names with the newer profiler. Such as: ðþH 147536 msec 203224 calls
Is there something that I can do so that plain text comes through?
_________________
jeffdavis_99
Nukingstreet Icewind Dales |
|
| Back to top |
|
|
jeffdavis_99
Joined: 17 Apr 2007
Posts: 4
Location: USA
|
| Posted: Sat May 24, 2008 19:29 Post subject: |
|
|
I have been testing 1.69 Beta 10 on my server and found that whenever I try to use the craft menu radial the server crashes consistently. I also tried switching the nwnx-module.dlls from version 2.6.1.0 to 2.7.0.0 with the same results. The logs show that the crash occurs as soon as the x2_im_polymorphed script is logged from the conversation file. This did not occur in 1.68 and I do not know if anything was changed in regards to this. I cannot find any documentation on this. When I test this from the regular nwn I do not have the same issue so I am thinking there is a conflict somewhere with 1.69 and nwnx but I am not very savvy on nwnx (probably evident by now  ).
_________________
jeffdavis_99
Nukingstreet Icewind Dales |
|
| Back to top |
|
|
virusman
Joined: 30 Jan 2005
Posts: 1020
Location: Russia
|
| Posted: Sat May 24, 2008 21:59 Post subject: |
|
|
| Yes, I have noticed crashes in the latest Profiler release. |
|
| Back to top |
|
|
|
FAQ
Search
Memberlist
Usergroups
Register
Profile
Log in to check your private messages
Log in
