0006012: [WATCHDOG] Timeout detected for thread ... Last tick was 0ms ago

(0021421)
justincc (administrator)
2012-05-12 02:16

How long after sim startup do these messages occur? Can you attach the portions of the log showing the timestamps?

(0021442)
kenvc (reporter)
2012-05-12 04:06

Justin,

These show up right after I see the message about logins being enabled, They may happen other times too but that's always when I notice them. I'll try to do a clean start-up tomorrow and send a larger hunk of the log file.

(0021446)
kenvc (reporter)
2012-05-12 13:30
edited on: 2012-05-12 13:32

Justin, Attached is the entire log file from the entire day of Thursday for one of my multi-sim instances that is rarely ever busy.

It is full of the Watchdog timeout errors even though the system was not busy at all.

(0021825)
justincc (administrator)
2012-07-19 22:57

Is this still occurring for you with current git master? What kind of machine are you running on?

(0021879)
argus Portal (reporter)
2012-07-24 20:27

I have this problem too. And when this happens, opensim.exe access very intensive to the harddisk (more than 35 MB/s).

This happens since the last updates (don't remember exactly when it's started)

(0021881)
justincc (administrator)
2012-07-24 23:21
edited on: 2012-07-24 23:21

There are many reasons for these messages and one of them is system contention, in which case your simulator is being delayed by reasons outside of OpenSimulator's control. This may be happening if something else that's causing a lot of hard disk activity is going on.

This is distinct from the extremely small timeout messages reported above which are a bug of some form.

(0021882)
argus Portal (reporter)
2012-07-25 03:02

It is opensim.exe that access to the harddisc. I can see it in ressourcemonitor in win7.

(0021900)
argus Portal (reporter)
2012-07-26 21:50

addition:

Often this happens in conjunction with this message:

[MAP IMAGE SERVICE MODULE]: something bad happened Ungültiger Parameter.

Translation: "Ungültiger Parameter" means "invalid parameter"

(0022032)
argus Portal (reporter)
2012-08-12 22:53

Now i am sure: The timeout is caused by the server-software itself: It is the very heavy access to the harddisc.

FIRST the harddisc is very busy because of opensim. And THEN the timeout-messages
fill the console. For every region there comes this block of messages:
______________________________________________________________________________

00:38:23 - [WATCHDOG]: Timeout detected for thread "MapItemRequestThread (altlan
d2)". ThreadState=Background. Last tick was 19063ms ago.
00:38:23 - [WATCHDOG]: Timeout detected for thread "Incoming Packets (altland2)"
. ThreadState=Running. Last tick was 18938ms ago. Data: Client is none
00:38:23 - [WATCHDOG]: Timeout detected for thread "Outgoing Packets (altland2)"
. ThreadState=WaitSleepJoin. Last tick was 16ms ago. Data: Client is none
00:38:23 - [WATCHDOG]: Timeout detected for thread "Heartbeat (altland2)". Threa
dState=WaitSleepJoin. Last tick was 0ms ago.
00:38:23 - [WATCHDOG]: Timeout detected for thread "Maintenance (altland2)". Thr
eadState=WaitSleepJoin. Last tick was 31ms ago.

(0022033)
kenvc (reporter)
2012-08-12 23:12

This still happens a lot if I have more that one instance starting at the same time. If I stagger the startup, it doesnt happen that often during normal operation. I have not noticed the 0ms timeout message lately, so that part may be fixed.

(0022034)
argus Portal (reporter)
2012-08-13 00:00

Here i have just one instance with 10 regions. (The serverstartup works well without problems.)

Some versions ago i don't had this problem. Unfortunately I can't remember the version where it has begun.

(0022054)
justincc (administrator)
2012-08-14 19:46

Yes, if this is happening at startup with heavy regions then it's because the cores are genuinely busy with other tasks. However, this is what one would expect at startup so in the future I may well make a refinement to delay the watchdog until startup has finished if this doesn't hide useful data.

The very low ms report probably occurs because the thread times out, but then it actually does get updated before the text which prints out the error condition. The logger needs to receive a copy of the ThreadWatchdogInfo rather than look at the original to prevent this happening.

(0022114)
justincc (administrator)
2012-08-17 23:00

I made a change to delay starting the thread watchdog until the regions are ready in git master 5a1b6fd. However, I still need to make the change where the reporting data is copied to avoid a race.

(0022116)
justincc (administrator)
2012-08-17 23:56

Okay, the second issue was addressed in git master e4e5237. This should stop these false alarms from occurring.

Issue History
Date Modified	Username	Field	Change
2012-05-07 09:24	kenvc	New Issue
2012-05-07 09:25	kenvc	Category	[REGION] Unhandled Packets => [REGION] OpenSim Core
2012-05-12 02:16	justincc	Note Added: 0021421
2012-05-12 04:06	kenvc	Note Added: 0021442
2012-05-12 13:27	kenvc	File Added: OpenSim.32BitLaunch.log.2012-05-10
2012-05-12 13:30	kenvc	Note Added: 0021446
2012-05-12 13:32	kenvc	Description Updated	View Revisions
2012-05-12 13:32	kenvc	Note Edited: 0021446	View Revisions
2012-07-19 22:57	justincc	Note Added: 0021825
2012-07-24 20:27	argus Portal	Note Added: 0021879
2012-07-24 23:21	justincc	Note Added: 0021881
2012-07-24 23:21	justincc	Note Edited: 0021881	View Revisions
2012-07-25 03:02	argus Portal	Note Added: 0021882
2012-07-26 21:50	argus Portal	Note Added: 0021900
2012-08-12 22:53	argus Portal	Note Added: 0022032
2012-08-12 23:12	kenvc	Note Added: 0022033
2012-08-13 00:00	argus Portal	Note Added: 0022034
2012-08-13 00:59	melanie	Summary	[WATCHDOG]: Timeout detected for thread ... Last tick was 0ms ago => [WATCHDOG] Timeout detected for thread ... Last tick was 0ms ago
2012-08-14 19:46	justincc	Note Added: 0022054
2012-08-14 19:47	justincc	Assigned To	=> justincc
2012-08-14 19:47	justincc	Status	new => assigned
2012-08-17 23:00	justincc	Note Added: 0022114
2012-08-17 23:56	justincc	Note Added: 0022116
2012-08-17 23:56	justincc	Status	assigned => resolved
2012-08-17 23:56	justincc	Resolution	open => fixed
2012-08-18 11:32	DMX04	Issue cloned: 0006178
2013-05-13 23:02	kenvc	Status	resolved => closed
2013-05-13 23:02	kenvc	Fixed in Version	=> master (dev code)

Notes
(0021421) justincc (administrator) 2012-05-12 02:16	How long after sim startup do these messages occur? Can you attach the portions of the log showing the timestamps?

(0021442) kenvc (reporter) 2012-05-12 04:06	Justin, These show up right after I see the message about logins being enabled, They may happen other times too but that's always when I notice them. I'll try to do a clean start-up tomorrow and send a larger hunk of the log file.

(0021446) kenvc (reporter) 2012-05-12 13:30 edited on: 2012-05-12 13:32	Justin, Attached is the entire log file from the entire day of Thursday for one of my multi-sim instances that is rarely ever busy. It is full of the Watchdog timeout errors even though the system was not busy at all.

(0021825) justincc (administrator) 2012-07-19 22:57	Is this still occurring for you with current git master? What kind of machine are you running on?

(0021879) argus Portal (reporter) 2012-07-24 20:27	I have this problem too. And when this happens, opensim.exe access very intensive to the harddisk (more than 35 MB/s). This happens since the last updates (don't remember exactly when it's started)

(0021881) justincc (administrator) 2012-07-24 23:21 edited on: 2012-07-24 23:21	There are many reasons for these messages and one of them is system contention, in which case your simulator is being delayed by reasons outside of OpenSimulator's control. This may be happening if something else that's causing a lot of hard disk activity is going on. This is distinct from the extremely small timeout messages reported above which are a bug of some form.

(0021882) argus Portal (reporter) 2012-07-25 03:02	It is opensim.exe that access to the harddisc. I can see it in ressourcemonitor in win7.

(0021900) argus Portal (reporter) 2012-07-26 21:50	addition: Often this happens in conjunction with this message: [MAP IMAGE SERVICE MODULE]: something bad happened Ungültiger Parameter. Translation: "Ungültiger Parameter" means "invalid parameter"

(0022032) argus Portal (reporter) 2012-08-12 22:53	Now i am sure: The timeout is caused by the server-software itself: It is the very heavy access to the harddisc. FIRST the harddisc is very busy because of opensim. And THEN the timeout-messages fill the console. For every region there comes this block of messages: ______________________________________________________________________________ 00:38:23 - [WATCHDOG]: Timeout detected for thread "MapItemRequestThread (altlan d2)". ThreadState=Background. Last tick was 19063ms ago. 00:38:23 - [WATCHDOG]: Timeout detected for thread "Incoming Packets (altland2)" . ThreadState=Running. Last tick was 18938ms ago. Data: Client is none 00:38:23 - [WATCHDOG]: Timeout detected for thread "Outgoing Packets (altland2)" . ThreadState=WaitSleepJoin. Last tick was 16ms ago. Data: Client is none 00:38:23 - [WATCHDOG]: Timeout detected for thread "Heartbeat (altland2)". Threa dState=WaitSleepJoin. Last tick was 0ms ago. 00:38:23 - [WATCHDOG]: Timeout detected for thread "Maintenance (altland2)". Thr eadState=WaitSleepJoin. Last tick was 31ms ago.

(0022033) kenvc (reporter) 2012-08-12 23:12	This still happens a lot if I have more that one instance starting at the same time. If I stagger the startup, it doesnt happen that often during normal operation. I have not noticed the 0ms timeout message lately, so that part may be fixed.

(0022034) argus Portal (reporter) 2012-08-13 00:00	Here i have just one instance with 10 regions. (The serverstartup works well without problems.) Some versions ago i don't had this problem. Unfortunately I can't remember the version where it has begun.

(0022054) justincc (administrator) 2012-08-14 19:46	Yes, if this is happening at startup with heavy regions then it's because the cores are genuinely busy with other tasks. However, this is what one would expect at startup so in the future I may well make a refinement to delay the watchdog until startup has finished if this doesn't hide useful data. The very low ms report probably occurs because the thread times out, but then it actually does get updated before the text which prints out the error condition. The logger needs to receive a copy of the ThreadWatchdogInfo rather than look at the original to prevent this happening.

(0022114) justincc (administrator) 2012-08-17 23:00	I made a change to delay starting the thread watchdog until the regions are ready in git master 5a1b6fd. However, I still need to make the change where the reporting data is copied to avoid a race.

(0022116) justincc (administrator) 2012-08-17 23:56	Okay, the second issue was addressed in git master e4e5237. This should stop these false alarms from occurring.

Relationships