locked
Performance Degradation in Thread which Outputs to the VS output window RRS feed

  • Question

  • We have implemented a package which enables us to perform of our custom elements. We face some issue with threading for our logging mechanism. We log the build output to the Visual Studio output window (using IVsOutputWindowPane). Our logging mechanism consists of two parts,

    1) An asynchronous log queue in C++ which queues up all the logs in a std::queue of bstrs. A thread pool task runs which pops each message from the queue and passes it to a listener.

    2) The listener in c# listens to each of these messages and outputs this into the Visual Studio output window.

    We find that using this mechanism there is a delay in the messages being logged. I created a separate thread and logged the messages (instead of a thread pool thread) and made it high piority one still the issue occurs.

    Earlier we had the listener also in c++ where everything was logged properly without delay. Also please not that this occurs only in a multiprocessor (not multi core) machine in Release mode.

    Please let me know if anyone has any clue about this. If this is not the right forum to post please guide me on where i can post it.

    Friday, January 7, 2011 11:59 AM

Answers

  • I wouldn't expect these issues only on a multi-proc system, but it may be the case that in a single proc system as soon as you try to call the output window the thread blocks (and the OS switches it out), if the OS then switches in the UI thread it may be able to quickly get to a point where it handles the RPC call from the background thread and thus the output window may appear to update more quickly.  In a multi-proc system it could be the case that the RPC call is making the background thread block, causing it to be switched out but the UI thread is already running on another proc, and perhaps already busy doing something (say idle time activities).  That is all speculation, your best bet would be to capture some profiling traces of the timespan in question so we can see what is going on exactly during that time.

    Ryan

    • Marked as answer by Victor_Chen Tuesday, January 18, 2011 7:29 AM
    Friday, January 7, 2011 6:18 PM

All replies

  • First, what version of VS is this?


    There is a lot going on here, so there are all kinds of possibilities.  First the output window is not MTA which means any calls to it off the UI thread will marshal back to the UI thread, this can be delayed if the UI thread is busy. Second the output window never immediately outputs things, it always buffers them and outputs in a batch. Third the cost of interop is going to make the C# solution slower than the native C++ one. In the native C++ one you are talking to a native C++ COM object so the only abstraction cost you have is in the COM layer, in the C# solution you have native->managed interop cost on your logger passing the message to your listener, then you have a managed->native transition cost + a COM layer in the C# code calling into the output window.

    How is your C# code adding messages to the output window?  DTE? The VS service interfaces?


    Ryan

    Friday, January 7, 2011 4:03 PM
  • Thanks Ryan. This was really helpful. We use VS2008.

    I am pretty interested in the threading fact especialy since this is reproduced only in release mode in a multi processor system. Else all other factors would have affected the logging anyways. We use the IVSOutpuWindow.OutputString to log to the VS Output window.

    Please let me know if the multiprocessor system could have any role to play especially in release mode here ?

    Friday, January 7, 2011 4:15 PM
  • I wouldn't expect these issues only on a multi-proc system, but it may be the case that in a single proc system as soon as you try to call the output window the thread blocks (and the OS switches it out), if the OS then switches in the UI thread it may be able to quickly get to a point where it handles the RPC call from the background thread and thus the output window may appear to update more quickly.  In a multi-proc system it could be the case that the RPC call is making the background thread block, causing it to be switched out but the UI thread is already running on another proc, and perhaps already busy doing something (say idle time activities).  That is all speculation, your best bet would be to capture some profiling traces of the timespan in question so we can see what is going on exactly during that time.

    Ryan

    • Marked as answer by Victor_Chen Tuesday, January 18, 2011 7:29 AM
    Friday, January 7, 2011 6:18 PM
  • Thanks Ryan.

    In the Output window, we display the timestamp as well. So we are able to see that the what is displayed at a particular time is something that is logged at an earlier time.

    We have actually found out which task is causing the delay. All the error and warning details, including the message, priority will be added to "TaskProvider.tasks" which run to update the error list. I am not sure if the TaskProvider runs in a separate thread or UI thread ? But i confirm that this indeed is causing the delay.

    Monday, January 10, 2011 7:39 AM
  • Ryan,

    Do you have any idea once we update the Error List window using the TaskProvider to update to the ErrorTask, is the delay being caused since the Error List is refreshed for each update ?

    Any clues on this ? Do you need more information ?

    Friday, February 4, 2011 6:36 AM