Weird behavior processing IEnumerable<AFEventFrame>

I have some code where I search for some event frames, then try to process the results.

The issue I have is that processing the IEnumerable results is very, very slow. It consistently takes my application time from 5 seconds to 45 seconds.

 

Here is the code:

        public void LoadClosedTasks(CurrentShift currentShift)
        {
            //CodeTimer LoadClosedTasksTimer = new CodeTimer();
            if (currentShift == null) return;
            List<AFSearchTokenBase> tokens = AppliedSearchTokens.ToList();                  //Copy the list
            tokens.RemoveAll(x => x.Filter == AFSearchFilter.InProgress);                   //Remove tokens for "In Progress"
            tokens.Add(new AFSearchValueToken("|COMPLETED_SHIFT_ID", currentShift.ShiftID.ToString()));
            IEnumerable<AFEventFrame> RetrievedFrames = null;
            using (AFEventFrameSearch search = new AFEventFrameSearch(LogDatabase, "baseSearch", tokens))
            {
                //DateTime searchStart = DateTime.Now;
                RetrievedFrames = search.FindObjects(0, true, 0);
            }
            ConcurrentBag<OperatorTask> createdFrames = new ConcurrentBag<OperatorTask>();  //Add to concurrent bag to avoid multi-thread issues.

            return;

            Parallel.ForEach(RetrievedFrames, frame =>
                {
                    //OperatorTask frameInstance = new OperatorTask();
                    //frameInstance.PopulateFromFrame(MainForm, frame, this);
                    //createdFrames.Add(frameInstance);

                });
            }

For info, this routine is called using an await Task.Run.

You can see where I place the "return" statement in the code, to bypass the Parallel.ForEach() block. With return there, the application loads (doing lots of other stuff) in 4.5 seconds. If I remove the return statement, the application takes 45 seconds. And this is with the code body in the Parallel.ForEach block commented out, as it shows above! It is not the code in the block that is slow, because there is no code running and I still get the problem.

I also tried a synchronous ForEach across the collection. Same issue.

This suggests to me that the simple act of enumerating the returned search is taking 40 seconds. (Timing it confirms that).

 

So... how many elements is it iterating?

 

Glad you asked. The search results are returning exactly 1 result!

 

Any idea on what is happening here? Search.FindObjects does have LoadFull set to true, but switching it to false doesn't help. Setting the page size doesn't help. I really am at a loss on how to fix this.

  • The fact that search.GetTotalCount() takes 40 seconds tells me that it will take at least 40 seconds to get your desired items. It does sound like you should be using server-side caching.

     

    I also think your timings are not measuring what you think it is. Consider this snippet of code:

     

    Stopwatch sw = Stopwatch.StartNew();
    
    IEnumerable<AFEventFrame> RetrievedFrames = null;
    using (AFEventFrameSearch search = new AFEventFrameSearch(LogDatabase, "baseSearch", tokens))
    {
        RetrievedFrames = search.FindObjects(0, true, 0);
    } // search object is disposed and any server-side cache is disposed.
    
    sw.Stop();

    The above code should be EXTREMELY fast. And here's why: because it has made ZERO calls to a remote server despite the search.FindObjects call being there. It actually has found 0 objects because it has not actually performed a search. Again, 0 RPC calls have been issued to the server. And no RPC calls will not be made UNTIL you enumerate over the first item.

     

    The below code gives the total possible count of event frames passing the server-side filter. In line 6 below, the first RPC is made to the remote server.

    Stopwatch sw = Stopwatch.StartNew();
    int supersetCount;
    using (AFEventFrameSearch search = new AFEventFrameSearch(LogDatabase, "baseSearch", tokens))
    {
        search.CacheTimeout = TimeSpan.FromMinutes(10);
        supersetCount = search.GetTotalCount();
    } // search object is disposed and any server-side cache is disposed.
    
    sw.Stop();

    So again, you really were not measuring how long it took to find anything. You were measuring how long it took to assign an IEnumerable object.

     

     

  • So again, you really were not measuring how long it took to find anything. You were measuring how long it took to assign an IEnumerable object.

     

    Thats my point. The search returns very fast. Anything that attempts to enumerate the search results takes 40 seconds. 40 seconds seems unreasonably long to me.

  • "The search returns very fast." This is not correct. Rather, the search BLOCK of code that you have executes very fast, but all you have really done is the overhead of merely defining a search.  YOU HAVE NOT ACTUALLY SEARCHED ON ANYTHING. An AFSearch is not being performed until the underlying client AF SDK code triggers an RPC to the AF Server, where the SQL Server hosting the PIFD database will actually search its SQL tables for event frame records. With your original code, no RPC's are issued, thus no search is made.

     

    AFSearch is keenly aware that it may make many RPC calls, which generally are considered expensive in terms of time. Therefore, AFSearch was intentionally designed to be lazy.  It defers on making an RPC until you absolutely request data, e.g with a foreach, a ToList (which itself calls a foreach), or something like search.GetTotalCount(). As is, the AFElementSearch.FindObjects returns a fairly minimal IEnumerable<AFEventFrame> object. Note the only method required by IEnumerable is GetEnumerator. There most likely is an internal page of items included with FindObjects result, but without enumerating over those items, that page is EMPTY. Which is why your code has the illusion of working extremely fast.  No search has actually been performed and you have an empty page of items.

     

    Also, a full load for event frames can be quite HEAVY. If you require client-side filtering, then you absolutely should perform a full load. But loading an event frame into memory does not just load the AFAttributes. It loads other child properties. And if the event frame was created by an analysis, it loads the analyses as well. That's what I mean by HEAVY.

     

    If it were me trying to trouble shoot, the first thing I want to know is how many items pass the server-side filter? Or to put that another way: how many event frames are being sent to me fully-loaded so that client-side filtering can be performed? I may be expecting a final result of 10 items, but what if 20K are being sent for client-side filtering? That's a big performance killer. If you have a large number of items being sent to the client, then you should try to refine the search to perform better filtering server-side to reduce what is sent to the client.

     

    But let's say that only 20 items pass server-side filtering. That should be a quick enough operation and should be fairly fast on the client. If this is what is happening to you, then all I can relate is 1 very rare case from a friend of mine.  

     

    His event frame search was expecting less than 5 items but was taking over a minute. No matter what we did to the code, including using a skinny search, it still was abnormally slow. The problem was completely external to AF and the PIFD. His PIFD used a shared TempDB and another rogue database on that SQL Server had written 30 million records to a temp table. Once his SQL Server admin cleaned up and truncated the TempDB, his AFSearch dropped down to less than 2 seconds. I do not know what steps are required to clean this up on the SQL Server side, so you may want to work with your own SQL Server admin.

     

    Also, I may be wrong but I am under the impression that you can defined a dedicated TempDB (e.g. "PIFD_TempDB") for just your PIFD, so that you are insulated from this happening again in the future.