private void SlowTimerCallback(object state)
{
try
{
int start = m_timerTickStart;
GameTimer timer = m_currentTimer;
if (timer == null)
{
return;
}
StringBuilder str = new StringBuilder("=== Timer already took ", 1024);
str.Append(GetTickCount() - start).Append("ms\n");
str.Append(timer.ToString());
str.Append("\n\n");
str.Append("Timer thread:\n");
str.Append(Util.FormatStackTrace(Util.GetThreadStack(m_timeThread)));
string packetStacks = PacketHandler.PacketProcessor.GetConnectionThreadpoolStacks();
if (packetStacks.Length > 0)
{
str.Append("\n\nPackethandler threads:\n");
str.Append(packetStacks);
}
str.Append("\n\nNPC update thread:\n");
str.Append(Util.FormatStackTrace(WorldMgr.GetNpcUpdateStacktrace()));
str.Append("\n\nRelocation thread:\n");
str.Append(Util.FormatStackTrace(WorldMgr.GetRelocateRegionsStacktrace()));
str.Append("\n\n");
lock (m_delayLog)
{
m_delayLog.Write(str.ToString());
m_delayLog.Flush();
}
}
catch (Exception e)
{
if (log.IsWarnEnabled)
{
log.Warn("collecting/writing timer delays", e);
}
}
}
/// <summary>
/// The time thread loop
/// </summary>
private void TimeThread()
{
log.InfoFormat("started timer thread {0} (ID:{1})", m_name, Thread.CurrentThread.ManagedThreadId);
int timeBalance = 0;
uint workStart, workEnd;
GameTimer chain, next, bucketTimer;
workStart = workEnd = (uint)GetTickCount();
#if MonitorCallbacks
Timer t = new Timer(new TimerCallback(SlowTimerCallback), null, Timeout.Infinite, Timeout.Infinite);
#endif
while (m_running)
{
try
{
// fire timers
lock (m_buckets)
{
if (DOL.GS.GameEvents.RegionTimersResynch.watch != null)
{
m_time = DOL.GS.GameEvents.RegionTimersResynch.watch.ElapsedMilliseconds;
}
else
{
m_time++;
}
int newTick = m_tick = (m_tick + 1) & TICK_MASK;
if ((newTick & BUCKET_MASK) == 0)
{
// cache next bucket
int index = newTick >> BUCKET_BITS;
next = m_buckets[index];
if (next != null)
{
m_buckets[index] = null;
// sort the new cached bucket
do
{
GameTimer timer = next;
next = next.m_nextTimer;
long index2 = timer.m_tick;
if ((index2 & LONGTERM_MASK) != 0 &&
((index2 -= 1 << TABLE_BITS + BUCKET_BITS) & LONGTERM_MASK) != 0)
{
// reinsert longterm timers back
timer.m_tick = index2;
bucketTimer = m_buckets[index];
m_buckets[index] = timer;
}
else
{
timer.m_tick = index2;
index2 &= CACHE_MASK;
bucketTimer = m_cachedBucket[index2].FirstTimer;
m_cachedBucket[index2].FirstTimer = timer;
if (m_cachedBucket[index2].LastTimer == null)
{
m_cachedBucket[index2].LastTimer = timer;
}
}
if (bucketTimer == null)
{
timer.m_nextTimer = null;
}
else
{
timer.m_nextTimer = bucketTimer;
}
}while (next != null);
}
}
int cacheIndex = m_tick & CACHE_MASK;
chain = m_cachedBucket[cacheIndex].FirstTimer;
if (chain != null)
{
m_cachedBucket[cacheIndex] = CacheBucket.EmptyBucket;
}
}
GameTimer current = chain;
int curTick = m_tick;
int currentBucketMax = (curTick & ~BUCKET_MASK) + BUCKET_MASK;
while (current != null)
{
if (current.m_tick == curTick)
{
try
{
long callbackStart = GetTickCount();
#if MonitorCallbacks
m_currentTimer = current;
m_timerTickStart = callbackStart;
t.Change(200, 100);
#endif
current.OnTick();
#if MonitorCallbacks
m_currentTimer = null;
t.Change(Timeout.Infinite, Timeout.Infinite);
if (GetTickCount() - callbackStart > 200)
{
lock (m_delayLog)
{
m_delayLog.Write("\n========================================================\n\n");
}
}
#endif
if (GetTickCount() - callbackStart > 250)
{
if (log.IsWarnEnabled)
{
string curStr;
try { curStr = current.ToString(); }
catch (Exception ee) { curStr = "error in timer.ToString(): " + current.GetType().FullName + "; " + ee.ToString(); }
string warning = "callback took " + (GetTickCount() - callbackStart) + "ms! " + curStr;
log.Warn(warning);
}
}
#if CollectStatistic
// statistic
int start = GetTickCount();
string callback;
if (current is RegionTimer)
{
callback = ((RegionTimer)current).Callback.Method.ToString();
}
else
{
callback = current.GetType().FullName;
}
lock (m_timerCallbackStatistic)
{
object obj = m_timerCallbackStatistic[callback];
if (obj == null)
{
m_timerCallbackStatistic[callback] = 1;
}
else
{
m_timerCallbackStatistic[callback] = ((int)obj) + 1;
}
}
if (GetTickCount() - start > 500)
{
if (log.IsWarnEnabled)
{
log.Warn("Ticker statistic " + callback + " took more than 500ms!");
}
}
#endif
}
catch (Exception e)
{
string curStr;
try { curStr = current.ToString(); }
catch (Exception ee) { curStr = "error in timer.ToString(): " + current.GetType().FullName + "; " + ee.ToString(); }
if (log.IsErrorEnabled)
{
log.Error("Timer callback (" + curStr + ")", e);
}
current.m_tick = TIMER_DISABLED | TIMER_RESCHEDULED;
}
m_invokedCount++;
}
else if ((current.m_tick & TIMER_RESCHEDULED) == 0)
{
// log.ErrorFormat("timer tick != current tick (0x{0:X4}), fired anyway: {1}", curTick, current);
try
{
current.OnTick();
}
catch (Exception e)
{
log.Error("timer error", e);
current.m_tick = TIMER_DISABLED | TIMER_RESCHEDULED;
}
}
lock (m_buckets)
{
next = current.m_nextTimer;
long tick = current.m_tick;
long interval = current.m_interval;
if ((tick & TIMER_DISABLED) != 0 || (interval == 0 && (tick & TIMER_RESCHEDULED) == 0))
{
m_activeTimers--;
current.m_nextTimer = null;
current.m_tick = TIMER_DISABLED;
current.m_targetTime = -1;
}
else
{
///// REINSERT all including rescheduled timers
if ((tick & TIMER_RESCHEDULED) != 0)
{
current.m_tick = tick &= ~TIMER_RESCHEDULED;
}
else
{
current.m_targetTime = (int)(CurrentTime + interval);
current.m_tick = tick = curTick + interval;
}
if (tick - curTick <= CACHE_MASK + 1)
{
tick &= CACHE_MASK;
current.m_tick &= TICK_MASK;
CacheBucket bucket = m_cachedBucket[tick];
GameTimer prev = bucket.LastTimer;
current.m_nextTimer = null;
if (prev != null)
{
prev.m_nextTimer = current;
bucket.LastTimer = current;
}
else
{
bucket.FirstTimer = current;
bucket.LastTimer = current;
}
m_cachedBucket[tick] = bucket;
}
else
{
if ((tick & TICK_MASK) > currentBucketMax)
{
current.m_tick = tick += TICK_MASK + 1; // extra pass if the timer is ahead of current tick
}
tick = (tick >> BUCKET_BITS) & TABLE_MASK;
bucketTimer = m_buckets[tick];
if (bucketTimer == null)
{
current.m_nextTimer = null;
}
else
{
current.m_nextTimer = bucketTimer;
}
m_buckets[tick] = current;
}
/////
}
}
current = next;
}
bucketTimer = null;
workEnd = (uint)GetTickCount();
timeBalance += 1 - (int)(workEnd - workStart);
if (timeBalance > 0)
{
Thread.Sleep(timeBalance);
workStart = (uint)GetTickCount();
timeBalance -= (int)(workStart - workEnd);
}
else
{
if (timeBalance < -1000)
{
// We can not increase forever if we get out of
// sync. At some point we have to print out a warning
// and catch up some time!
if (log.IsWarnEnabled && timeBalance < -2000)
{
// Again, too much warning spam is meaningless. Will warn if time sync is more than the typical 1 to 2 seconds
// -tolakram
log.Warn(Name + " out of sync, over 2000ms lost! " + timeBalance.ToString());
}
timeBalance += 1000;
}
workStart = workEnd;
}
}
catch (ThreadAbortException e)
{
if (log.IsWarnEnabled)
{
log.Warn("Time manager thread \"" + m_name + "\" was aborted", e);
}
m_running = false;
break;
}
catch (Exception e)
{
if (log.IsErrorEnabled)
{
log.Error("Exception in time manager \"" + m_name + "\"!", e);
}
}
}
log.InfoFormat("stopped timer thread {0} (ID:{1})", m_name, Thread.CurrentThread.ManagedThreadId);
}
