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); }