none
ICorProfilerEvents out of sequence. RRS feed

  • Question

  • Hi everybody. I am working on a profiling agent. Among other things it analyzes the active threads' status. To be successful it has to match thread names to IDs. Here is a problem though: When I run a simple test case that creates several threads and sets a name for each one, I get ThreadNameChanged notifications fired before ThreadCreated. Below is WinDbg output from breakpoints set for the appropriate events:

    ModLoad: 000007fe`e57f0000 000007fe`e5aa4000   C:\vlh\Builds\X64\My\OciVOB\DevInstall_debug\X64\Purify.rsc
    ThreadCreated 9021472
    ThreadCreated 9130704
    ModLoad: 000007fe`de930000 000007fe`dee1a000   mscorlib.dll
    ModLoad: 00000000`04c70000 00000000`0515a000   mscorlib.dll
    ModLoad: 000007fe`fb7b0000 000007fe`fb7bc000   C:\Windows\system32\VERSION.dll
    ModLoad: 000007fe`de930000 000007fe`dee1a000   C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
    ModLoad: 000007fe`eb990000 000007fe`ebac1000   C:\Windows\Microsoft.NET\Framework64\v4.0.30319\clrjit.dll
    ThreadNameChanged 86305504 Test_0
    ThreadNameChanged 86386128 Test_1
    ThreadNameChanged 86389968 Test_2
    ThreadNameChanged 86393808 Test_3
    ThreadNameChanged 86397648 Test_4
    ThreadNameChanged 86358608 Test_5
    ThreadNameChanged 86361872 Test_6
    ThreadNameChanged 86365136 Test_7
    ThreadNameChanged 86368976 Test_8
    ThreadNameChanged 86372816 Test_9
    ThreadCreated 86305504
    ThreadCreated 86386128
    ThreadCreated 86389968
    ThreadCreated 86393808
    ThreadCreated 86397648
    ThreadCreated 86358608
    ThreadCreated 86361872
    ThreadCreated 86365136
    ThreadCreated 86368976
    ThreadCreated 86372816

    The problem is: I register thread information on ThreadCreated event and then update it as other events come in, so out-of-sequence events throw the analysis off.

    Of course I can map thread IDs to thread information blocks and re-sequence the incoming events. But common, doesn't this violate the whole "Cause and effect" premise?

    Regards,

    Victor

    Friday, May 2, 2014 9:19 PM

All replies

  • Hi Victor,

    >The problem is: I register thread information on ThreadCreated event and then update it as other events come in, so out-of-sequence events throw the analysis off.

    As I know, this thread is more related to language issue. Such as C# or C++. Please post your thread on appropriate forum.

    C# http://social.msdn.microsoft.com/Forums/vstudio/en-US/home?forum=csharpgeneral.

    C++ http://social.msdn.microsoft.com/Forums/vstudio/en-US/home?forum=vcgeneral.

    If you have profiling problem, please post on profiling forum. http://social.msdn.microsoft.com/Forums/vstudio/en-US/home?forum=vsdebug.

    Thank you for understanding.

    Regards,


    We are trying to better understand customer views on social support experience, so your participation in this interview project would be greatly appreciated if you have time. Thanks for helping make community forums a great place.
    Click HERE to participate the survey.

    Monday, May 5, 2014 3:35 AM
    Moderator
  • I respectfully disagree. ICorProfilerCallback interface is deeply rooted in the CLR framework and the events are generated by the CLR engine (MSCorWKS/CLR) in conjunction with JIT-generated hooks. These events are language neutral. If I posted such question on any language related forum, any CLR expert would rightfully redirect me back here. The profiling forum above is dedicated to Microsoft profiling tools shipped with Visual Studio and is not directly related to CorProfiler interfaces. If you need confirmation from an expert, you can talk to Lee Culver at the Dot Net CLR team.

    Ragards,

    Victor


    Monday, May 5, 2014 4:55 PM
  • This is the right forum.

    Which events are out of sequence? Does it happen always or only sometimes?

    -Karel

    Wednesday, May 14, 2014 2:15 AM
    Moderator
  • Hi Karel.

    ICorProfilerCallback2:ThreadNameChanged event is coming before ICorProfilerCallback::ThreadCreated. See the log file above.This is happening consistently when I run the code below with CorProfiler enabled. From what I can tell from debugging the CLR code, this is happening whenever a thread name is changed before Thread.Start() method is invoked. The problem is that CLR fires the ThreadCreate callback not when a new thread object is created, but when the thread is started. In my view this is not a very good approach. It would be much more convenient if the ThreadCreated event would fire when a thread object was created and some other event (say ThreadStarted) would fire when the thread got started. Another approach is to use ThreadAssignedToOSThread event to mark both thread start and OS thread attachment. In the current implementation ThreadCreated and ThreadAssignedToOSThread seem redundant and the real ThreadCreated event is missing.

    --- The code snippet below this line ---

    using System;
    using System.Collections.Generic;
    using System.Linq;
    using System.Text;
    using System.Threading;
    using System.Timers;

    namespace Threads
    {
        public class ThreadSink
        {
            private ThreadStart ts;
            protected Thread[] m_threads;
            protected int m_nThreads = 0;

            public ThreadSink(int i_nThreads)
            {
                ts = ThreadEntry;
                m_nThreads = i_nThreads;
                m_threads = new Thread[m_nThreads];
                for (int n = 0; n < m_nThreads; n++)
                {
                    m_threads[n] = new Thread(ts);
                }
                for (int n = 0; n < m_nThreads; n++)
                {
                    m_threads[n].Name = string.Format("Test_{0}", n);
                }
            }

            public virtual void Run() {}
            public virtual void ThreadEntry() {}

        };

        public class ThreadSinkRun : ThreadSink
        {
            private bool m_bRun = true;

            public ThreadSinkRun(int i_nThreads) : base(i_nThreads) {}

            public override void Run()
            {
                foreach (Thread t in m_threads)
                {
                    t.Start();
                }
                System.Console.ReadKey(true);
                m_bRun = false;

            }

            public override void ThreadEntry()
            {
                while (m_bRun)
                {
                    byte[] buf = new byte[1000];
                    Thread.Sleep(10);
                }
                return;
            }

        };

        public class ThreadSinkWait : ThreadSink
        {
            private EventWaitHandle evt;

            public ThreadSinkWait(int i_nThreads) : base(i_nThreads) { }

            public override void Run()
            {
                evt = new EventWaitHandle(false, EventResetMode.ManualReset);

                foreach (Thread t in m_threads)
                {

                    t.Start();

                }
                System.Console.ReadKey(true);
                evt.Set();

            }

            public override void ThreadEntry()
            {
                byte[] buf = new byte[1000];
                evt.WaitOne();
                return;
            }

        };

        class Program
        {
            [MTAThread]
            static void Main(string[] args)
            {
                //ThreadSink ts = new ThreadSinkWait(10);
                ThreadSink ts = new ThreadSinkRun(10);
                ts.Run();
            }
        }
    }

    Wednesday, May 14, 2014 5:31 AM
  • Hello Victor,

    Sorry that I missed that info earlier. I passed your question to Profiler team, they will try to answer next week (some of them are on vacation currently).

    I hope that is alright,
    -Karel

    Thursday, May 15, 2014 4:14 PM
    Moderator
  • Hi Karel,

    Thank you for taking care of this. Of course it can wait. It worked like that at least for 10 years since CLR2 was introduced. Given this behavior became de facto standard, I do not see how it can be addressed in the existing framework. I hope that in the future framework (CLR5?) Dot Net team can introduce an additional even to address this issue. For example CLRThreadCreated(ThreadID id). If this event gets fired when a Thread object gets created, this will solve the problem.

    Regards,

    Victor

    Thursday, May 15, 2014 4:27 PM