Sources of delays in starting a scheduled activity RRS feed

  • Question

  • I have an interesting problem with a NativeActivity with child activities that has me scratching my head ...

    Basically, I have a NativeActivity<TResult> derived activity that does a bit of database work in its Execute method to create a couple of values. It has a ContentProperty of type ActivityAction<string,string>, with two DelegateInArgument<string> arguments defined.

    After grabbing the information it needs from the database, it simply does a ScheduleAction<string,string> call on the NativeActivityContext.

    The thing that has me puzzled -- there's a consistent three second lag from the point that ScheduleAction is called, and the content activity (no matter what type it is) starts executing. The code has quite a bit of trace logging, so I can see the Execute method itself has exited immediately, prior to the lag, so I know the time isn't being spent in Execute of the parent activity. In fact, I can see the whole process of running the DB call and calling ScheduleAction takes a couple of milliseconds.

    The activity tracing for the part involved in this looks like this:

    Activity [1.28] "WaitForCallback" is Executing { InstanceId: 6655ffa8-5910-4a4b-aed1-eee7367daab2 Event Time: 06:57:15.1320 Arguments Timeout: 1.00:00:00 }
    Activity [1.28] "WaitForCallback" scheduled child activity [1.29] "Send" { InstanceId: 6655ffa8-5910-4a4b-aed1-eee7367daab2 Event Time: 06:57:18.4907 }
    Activity [1.29] "Send" is Executing { InstanceId: 6655ffa8-5910-4a4b-aed1-eee7367daab2 Event Time: 06:57:18.5063 }

    I can see in the standard trace logs that the call to schedule the activity happened at 6:57:15, and the method exited immediately after. In the above trace, the "scheduled child activity" event happens three seconds later, and then the activity starts executing. Those are ActivityStateRecord, ActivityScheduledRecord, and ActivityStateRecord, respectively.

    Clearly the ScheduleActivity<string,string> call is asynchronous, and something is delaying it starting the next activity in the workflow. Unfortunately, the MSDN documentation is lousy about the exact sequence of events that happens in the scheduling of the activities.

    So I have two questions:

    - What impacts the scheduling of activities in a workflow? I've gone as far as decompiling the core activities and looking at what they do, and they also call ScheduleAction the same way, and don't seem to have any lag.

    - Is there any better way of tracing the workflow engine at a finer granularity than the TrackingParticipant mechanism? (It, obviously from above, doesn't have enough detail it seems to diagnose this.)


    Tuesday, April 2, 2013 11:58 AM