15 Replies Latest reply on Jan 27, 2017 6:23 PM by ekuwana

    PiPoint.RecordedValuesAtTimes performance




      We've encountered a behavior that is quite surprising using the PiPoint.RecordedValuesAtTimes.

      The below results are all from requesting 10000 values from a one hour time span.

      Pi point has one recorded value every second for requested time span, time to complete call 158,7 milliseconds (satisfactory performance)

      Pi point has ten recorded values every second  for requested time span, time to complete call 204,3 milliseconds (29% slower, kind of expected)

      Pi point has one recorded value every 30 seconds for requested time span, time to complete call 3893 milliseconds (2443% slower, unexpected)


      Can anyone explain this behavior (in particular, why the last request takes so much more time to complete).

      The output we want is exactly what this function provides, is there some other way we can get the same information using a different approach?

      To anyone from Osisoft: Is this a known issue?


      Btw, we have also tried AFCalculation.CalculateAtIntervals with the expression "PrevVal(piPoint.Name)". This is almost 50% slower than the one mentioned above (but the relative differences in the various scenarios are about the same).

        • Re: PiPoint.RecordedValuesAtTimes performance

          HI Sigmund,


          Can you show us a snippet of your code you are using for performance testing of PiPoint.RecordedValuesAtTimes?

            • Re: PiPoint.RecordedValuesAtTimes performance




              const int numberOfValues = 10000;

              var fromTime = DateTime.Now.AddHours(-2);

              var startTime = new AFTime(fromTime);

              var endTime = new AFTime(fromTime.AddHours(1));

              var afTimeRange = new AFTimeRange(startTime, endTime);

              var dblInterval = toTime.Subtract(fromTime).TotalMilliseconds / numberOfValues;

              var ts = new AFTimeSpan(milliseconds: dblInterval);

              var times = ts.GetIntervalTimes(afTimeRange);


              var before = DateTime.Now;

              var afValues = piPoint.RecordedValuesAtTimes(times, OSIsoft.AF.Data.AFRetrievalMode.AtOrBefore);

              var timeTaken = DateTime.Now - before;           


              Debug.WriteLine("Total milliseconds used: {0}", timeTaken.TotalMilliseconds);

                • Re: PiPoint.RecordedValuesAtTimes performance

                  Hi Sigmund,

                  I am not seeing the performance issues you are seeing with this code and I have not found any information about a performance issue with PiPoint.RecordedValuesAtTimes. Are you running PI Data Archive 2016? Also, what is the reason to run this method? Are you looking for specific times or interpolated?   

                    • Re: PiPoint.RecordedValuesAtTimes performance

                      Hi Butch.

                      - I'm seeing this behavior on both 2015 and 2016 versions of PI.

                      - The reason to run this method is because of the requirements for the software I'm working on. The client will request a time span and an interval. Values should be returned for each interval in the specified time span. However the values should not be interpolated. For each time stamp the previous known value should be returned (will result in a graph that looks like a staircase for an increasing integer for instance).

                        • Re: PiPoint.RecordedValuesAtTimes performance
                          Rick Davin

                          Hi Sigmund,


                          Earlier you said you've seen the issue for both 2015 and 2016 versions of PI.  Please clarify that by "PI" you did in fact mean PI Data Archive (formerly PI Server).


                          For PI Data Archive 2015, sluggish performance is no surprise.  It's not apparent from RecordedValueAtTimes Help, but if you scroll to the very bottom you will see it states: AFSDK Supported in: 2.8.5, 2.8.  Again, not apparent in the help text but AF 2.8 was released with PI AF 2016.  I can use LiveLibrary to review What's New specifically for PI AF 2016.  Since RecordedValuesAtTimes is a method in the AFData class, I can jump to the OSIsoft.AF.Data Namespace section in What's New.  The first paragraph in the Data section states:


                          To get values as specific times, the AFData. RecordedValuesAtTimes and AFListData. RecordedValuesAtTimes methods have been added. These methods require the PI Data Archive 2016 or later to take full advantage of the performance gains.


                          This tells me that it should be no surprise about sluggish performance with PI Data Archive 2015.  I would ask you to double-check that the same poor performance is indeed witnessed with PI Data Archive 2016.  Contrasting PI Data Archive 2015 to 2016, is 2016 as slow as 2015, slower than 2015, or faster than 2015 but still slow?




                          1 of 1 people found this helpful
                  • Re: PiPoint.RecordedValuesAtTimes performance

                    Hi Sigmund,


                    My suspicion is that this behavior you are describing can be explained by the bottleneck experienced by almost any kind of query (not just PI) to a server: the limitations of disk I/O. The fact that your query for per-second (1 Hz) data returns faster could be explained by the fact that most of these events are probably within the same archive file, and likely still in memory (either the Windows File System Cache or PI Archive Subsystem's private read cache). On the other hand, it is more likely that the events for your per-30-seconds data spans multiple archive files, or at least is more dispersed in the archive file, and is likely to be coming from disk.


                    How many times total did you run your test, and did the results differ between tests? For example, I expect that the first time any query is run for any given data, it should need to come from disk. However, subsequent queries should be able to hit the data which is now loaded in memory. If you re-run your tests, do you find that the subsequent queries return faster?


                    In my experience, query performance limitations pretty much always come from disk I/O. To further verify that the bottleneck is from disk I/O, you could use the disk performance counters provided by Windows on the server, or various utilities such as RAMMap, ProcessMonitor, etc. If you would like to discuss this topic more, or troubleshoot more thoroughly, just let me know .

                      • Re: PiPoint.RecordedValuesAtTimes performance

                        Hi Gavin.


                        First let me answer your questions:

                        - I've ran the tests many times, and the results are pretty similar every time. (The results in the first post are average values from multiple tests). I have not tried requesting the same values multiple times in the same tread, but that is not a relevant test for the software I'm making (an API for providing values to trend applications and tools for exporting data). If i run the tests once, and then rerun them right away, the next set of results are pretty similar (sometimes a bit faster, sometimes a bit slower).


                        Regarding you first paragraph, I think you have misunderstood the initial post a little bit. Inn all the queries, i'm asking for the same type of data (10000 values for a one hour time span, so 3.6 samples per second). The only difference is that the raw values stored have a different frequency. So the actual data points should span the same amount of archive files (the requested time frame is the same for all tests). Probably all the values are in a single archive file.


                        I will try to set up a even more isolated test to see if I can narrow the problem down even further.

                          • Re: PiPoint.RecordedValuesAtTimes performance

                            Hi Sigmund,


                            So the difference is in the amount of archived events for the raw points?

                            Could you please query the count and post how many archive events you see for each individual PI Point over the query period?


                            To evaluate the results, PI Archive Subsystem needs to query all archived events for the period and build the result set for your query. It less depends on the size of the result set but on the amount of archived events within the query period how long it takes to make the data available. You mentioned that subsequent executions don't perform a lot better. This indicates that the amount of data exceeds the archive cache so your queries do not take advantage of the cache. You can try querying smaller time periods to evaluate a query period that would benefit from the cache. While it is possible to increase the cache size (if the memory resources allow this), my suspicion is that you are archiving too many events e.g. because of not making use of Exception and Compression. Another common issue is that data becomes recorded with sub second timestamps where the sub second portion doesn't add additional value. Without sub seconds, PI Archive Subsystem stores the offset in full seconds based on the previous event but with sub seconds, PI Archive Subsystem stores the complete Timestamp information which requires a lot more space and causes that records become filled quicker which causes more overflow records are needed. More important than the space on disk is the fact that because of this data retrieval is way slower. And here's where disk performance starts playing a big role as pointed out by Gavin Chen.


                            For your purpose, why aren't you using PlotValues? It's not that I would expect it to perform a lot faster but the algorithm behind this function is optimized to include data which allows to render a representative trace based on the amount of pixels available (specified with the interval parameter).

                              • Re: PiPoint.RecordedValuesAtTimes performance

                                Hi Gregor

                                I'll explain how the test is performed, to make it a bit more clear.


                                Create two PI points with identical settings.

                                Record values for the two points for a one hour time span (3600 values for point #1, 120 values for point #2, evenly spread out across the hourly time span). When inserting the values the "Insert with no compression" option is used.


                                Then request RecordedValuesAtTimes for each PI point and record the time used to complete each call.


                                I will add some code shortly which shows the entire test.


                                If the client (of our API) request plot values, then we use the PlotValues, but that function does not satisfy the requirements for the scenario where we're using RecordedValuesAtTimes.

                              • Re: PiPoint.RecordedValuesAtTimes performance
                                Roger Palmen

                                Nice puzzle... This comment at least rules out some parts of PI Server tuning as the dataset is always roughly the same size. On the same line, one would expect issues with reading through the archive files. But nothing sensible to add to the discussion. Curious about the outcome!

                                • Re: PiPoint.RecordedValuesAtTimes performance

                                  Hi Sigmund,


                                  Sorry in advance for the long post, but hopefully this explains my thought process clearly...


                                  When I wrote my first response, I was not sure that the "one hour time span" was the same time span for each of your points (I had thought you were querying by the 10k event count, rather than by a time span). So I was not certain that all of the data for each point would be in the same archive file. However, even if all the data is within the same archive, it does still matter where physically within the archive file that the data is, which can be affected by the frequency of the data. This is important with regards to disk, because if the data is indeed being read from disk, traditional HDDs do better reading sequential blocks rather than random blocks. I was also not aware that you were deleting and recreating the points every time - I assumed that you were using the same points and data between tests.


                                  That being said though, thanks a lot for clarifying your scenario and providing the test code. I have been able to reproduce the behavior using your code, and I understand better what is going on. Indeed, this particular problem (at least with the scale of your unit test code) does not seem to be disk related. I simplified your unit tests down to just "CompareTimeGettingValuesForSignalsWith100MillisecondInterval", because this test provided the greatest difference between the retrieval times of the two points. On my system (PI Data Archive 2016 R2, probably not as well spec'ed out as yours), I initially got the following results, with per-minute data taking almost 3 times as long:


                                  Time(ms) getting values for point with one value per second: 15852.9058

                                  Time(ms) getting values for point with one value per minute: 43011.4753


                                  As Eddy indicates, this time is almost completely the time it takes the RPC to execute on the server (I checked this using 'piartool -thread piarchss -history' on the server, whereas Eddy checked client side using AFGetTrace). However, this fact alone does not preclude that the issue is not disk-related, since disk operations times would be rolled up in this RPC execution time. So at this point, I attached a debugger to PI Archive Subsystem to see what was going on. Interestingly, I noticed that the per-minute point was making many more "GetEndOfStream" calls, which is demonstrated from this screenshot of the GetEndOfStream Calls/sec perfmon counter from PI Snapshot Subsystem:



                                  Notice that there are two "spikes": the first for the query to the per-second point, and the second for the query to the per-minute point. The gap in between is from a Thread.Sleep(5000) that I added to the unit test between the queries for the two points, to more clearly demarcate the two regions. Just from looking at this trend alone, we can see that the second query spends roughly 42 seconds (out of ~43 total) just making GetEndOfStream calls (including everything in between sequential GetEndOfStream calls)! And naturally this will be slower and take more time, because GetEndOfStream (which is executed by PI Snapshot Subsystem) represents inter-process communication (PI Archive Subsystem making RPCs to PI Snapshot Subsystem). So this gives us a pretty good idea now why the query for the per-minute data takes longer. In other words, for this particular pattern of writing and querying the data, we would want to minimize the GetEndOfStream calls for best performance. However, now the question is: why does the per-minute data make so many more of these GetEndOfStream calls?


                                  After looking a little more at the source code of PI Archive Subsystem, I determined that the general order of operations that Archive Subsystem follows when trying to find an event at or after a given time is:

                                  1. Check the archive files
                                  2. If not in archive files, then check the snapshot (from GetEndOfStream)
                                  3. Check the write cache


                                  According to this logic, Archive only calls GetEndOfStream if a suitable event is not found in the archive files first. So why would it be that the per-minute point would make more of these calls, implying that each of these calls means there is no suitable event found in the archive? This has to do with two tune-able parameters which control when flushes are made from the write cache to the archive file on disk: Archive_MaxWriteCachePerPoint and Archive_SecondsBetweenFlush. By default, these parameters dictate that Archive Subsystem will flush events to the archive periodically every 5 minutes, or every 256 events (per point), whichever occurs first. At least in the unit test code provided, the per-minute point writes a total of 61 events, clearly not enough to trigger a flush yet. And because the read query is made almost immediately after writing the data, the 5 minute trigger is not hit either. This essentially means that none of the events will be found in step 1 above, and every request for an event will result in a GetEndOfStream call, before finding the target event in the write cache in step 3 (except of course the final event, which should be the GetEndOfStream return). With a time span of one hour and a 100 millisecond interval, Archive Subsystem will look for 36000 events. For the per-minute point, this will pretty much guarantee 36000 GetEndOfStream calls as well. This also means that as you decrease the interval (say, from 100 milliseconds to 10 milliseconds) for your GetRecordedValuesAtTimes call, the performance for the per-minute point will degrade even more with respect to the per-second point, since it's compounded by the increase in the count of intervals. The reason for the small spike in GetEndOfStream calls for the per-second point is because 3601 events is not exactly a multiple of 256. So 3584 (256 * 14) events are getting flushed immediately to disk upon write, then the query will still need to make 17 GetEndOfStream calls before finding the remaining events in the write cache (and final event in snapshot).


                                  Now, to test the hypothesis I tried two methods. First, I put a pause between when the tester wrote the values, and when it queried for them. During this pause, I manually forced a flush of everything in the write cache using 'piartool -flush'. Note the following results:


                                  Time(ms) getting values for point with one value per second: 10797.7219

                                  Time(ms) getting values for point with one value per minute: 9500.5928


                                  With this test, it's now actually slightly faster to query for the per-minute data, likely because there's fewer archive records to navigate through than for the per-second data. Using the test code as-written, there are still some inefficient GetEndOfStream calls being made at the end. For example, the per-minute data will write the last value at _dataEndTime - 1 minute, while the query intervals still exist within this last minute window. In the context of 100 millisecond intervals, this accounts for an extra 600 intervals which will each call GetEndOfStream and find nothing.


                                  The second test I did was to change the tuning parameter Archive_MaxWriteCachePerPoint to 60, so that each per-minute event would be flushed to the archive files. As expected, this produced very similar results to the flush test:


                                  Time(ms) getting values for point with one value per second: 10218.7358

                                  Time(ms) getting values for point with one value per minute: 9118.5905


                                  So in conclusion, I believe that the main difference in the query times stems from the inefficiencies of the inter-process GetEndOfStream RPCs being made. Using the same perfmon counter as shown, are you able to see the same GetEndOfStream calls and behavior? Are you able to see significant improvement with the flush tests? I think this is definitely a very interesting outcome, and I will speak to the PI Data Archive developers to get their feedback on this behavior. At this point, I don't want to jump to conclusions and say that it is a bug, since the logic could have been written this way purposefully. For example, the order of operations above makes sense probably for most cases, where the data has already been flushed to the archives. In this particular case, because the points are always being deleted and recreated, and because we are querying immediately for data we just wrote, we almost always encounter situations where some, if not all, of the data has not yet been flushed.


                                  Hope that helps, and let me know if anything is unclear. It is now almost 1 AM here in California, so I think the statement 'if (GetEndOfDay() == now) then Me.Sleep();' is finally true.



                                  P.S., normally it's not recommended to reduce the Archive_MaxWriteCachePerPoint too low because its intention is to prevent inefficient disk I/O when writing events. For example, you wouldn't want to spin the disk for every single event that's written. The use of the parameter here was purely for demonstration purposes and not meant to be a recommendation for production.

                                  5 of 5 people found this helpful
                              • Re: PiPoint.RecordedValuesAtTimes performance

                                I've made some code now which demonstrates this issue. All you need to run it should be .Net 4.5, latest AF SDK and NUnit.

                                For those not familiar with NUnit, the function with the [TestFixtureSetUp] attribute will be executed once at the start. Then all the functions with [Test] attribute will be executed. Finally the [TestFixtureTeardDown] will be executed.


                                (I tried to find some way to attach the file or use <code> tags, but failed, so I'll just copy and paste the code as plain text)


                                using System;
                                using System.Collections.Generic;
                                using System.Diagnostics;
                                using System.Threading;
                                using NUnit.Framework;
                                using OSIsoft.AF.Asset;
                                using OSIsoft.AF.Data;
                                using OSIsoft.AF.PI;
                                using OSIsoft.AF.Time;
                                namespace Tests
                                    public class PiPointRecordedValuesAtTimesSimpleTest
                                        private const string PiPointNameOneValuePerSecond = "TmpPiPointOneValuePerSec";
                                        private const string PiPointNameOneValuePerMinute = "TmpPiPointOneValuePerMin";
                                        private const string PiServerName = ""; //this is obviously specific for my environment
                                        private PIServer _piServer;
                                        private PIPoint _piPointOneValuePerSecond;
                                        private PIPoint _piPointOneValuePerMinute;
                                        private DateTime _dataStartTime;
                                        private DateTime _dataEndTime;
                                        public void OneTimeSetup()
                                            var piServers = new PIServers();
                                            _piServer = piServers[PiServerName];
                                            var pointAttributes = new Dictionary<string, object>
                                                {"PointType", PIPointType.Float32},
                                                {"PointSource", "Test"},
                                                {"Excdev", 0},
                                                {"Excmax", 10},
                                                {"Compressing", true},
                                            //create the pi points
                                            _piPointOneValuePerSecond = _piServer.CreatePIPoint(PiPointNameOneValuePerSecond, pointAttributes);
                                            _piPointOneValuePerMinute = _piServer.CreatePIPoint(PiPointNameOneValuePerMinute, pointAttributes);
                                            //generate values
                                            _dataStartTime = DateTime.UtcNow.AddHours(-3);
                                            _dataEndTime = _dataStartTime.AddHours(1);
                                            var valuesOnePerSecond = CreateAfValues(_piPointOneValuePerSecond, _dataStartTime, _dataEndTime, 1000);
                                            var valuesOnePerMinute = CreateAfValues(_piPointOneValuePerMinute, _dataStartTime, _dataEndTime, 60000);
                                            //write values to PI points
                                            var results = _piServer.UpdateValues(valuesOnePerSecond, AFUpdateOption.InsertNoCompression);
                                            if (results != null && results.HasErrors) Assert.Inconclusive("Error when writing PiPoint values");
                                            results = _piServer.UpdateValues(valuesOnePerMinute, AFUpdateOption.InsertNoCompression);
                                            if (results != null && results.HasErrors) Assert.Inconclusive("Error when writing PiPoint values");
                                            Thread.Sleep(5000); //wait a little bit before requesting the values          
                                        public void OneTimeTeardown()
                                        public void CompareTimeGettingValuesForSignalsWith100MillisecondInterval()
                                            var times = GetTimes(100, _dataStartTime, _dataEndTime);
                                        public void CompareTimeGettingValuesForSignalsWith1000MillisecondInterval()
                                            var times = GetTimes(1000, _dataStartTime, _dataEndTime);
                                        public void CompareTimeGettingValuesAfterLastRecordedPointWith100MillisecondInterval()
                                            var times = GetTimes(100, _dataEndTime, _dataEndTime.AddMinutes(30));
                                        public void CompareTimeGettingValuesAfterLastRecordedPointWith10000MillisecondInterval()
                                            var times = GetTimes(1000, _dataEndTime, _dataEndTime.AddMinutes(30));
                                        private void ReadValuesForTimesForBothPiPoints(IList<AFTime> times)
                                            var timeForPointOneValuePerSec = GetRecordedValuesAtTimes(_piPointOneValuePerSecond, times);
                                            var timeForPointOneValuePerMinute = GetRecordedValuesAtTimes(_piPointOneValuePerMinute, times);
                                            Debug.WriteLine("Time(ms) getting values for point with one value per second: " + timeForPointOneValuePerSec.TotalMilliseconds);
                                            Debug.WriteLine("Time(ms) getting values for point with one value per minute: " + timeForPointOneValuePerMinute.TotalMilliseconds);
                                        private TimeSpan GetRecordedValuesAtTimes(PIPoint piPoint, IList<AFTime> times)
                                            var before = DateTime.Now;
                                            var values = piPoint.RecordedValuesAtTimes(times, AFRetrievalMode.AtOrAfter);
                                            var time = DateTime.Now - before;
                                            Assert.AreEqual(times.Count, values.Count);
                                            return time;
                                        private static IList<AFTime> GetTimes(int millisecondInterval, DateTime startTime, DateTime endTime)
                                            var timeSpan = new AFTimeSpan(TimeSpan.FromMilliseconds(millisecondInterval));
                                            var timeRange = new AFTimeRange(startTime, endTime);
                                            return timeSpan.GetIntervalTimes(timeRange);
                                        private List<AFValue> CreateAfValues(PIPoint piPoint, DateTime startTime, DateTime endTime, int millisecondFrequency)
                                            var values = new List<AFValue>();
                                            var value = 0;
                                            var currTime = startTime.AddMilliseconds(-millisecondFrequency);
                                            while (currTime.Ticks < endTime.Ticks)
                                                values.Add(new AFValue(value, new AFTime(currTime))
                                                    PIPoint = piPoint
                                                currTime = currTime.AddMilliseconds(millisecondFrequency);
                                            return values;


                                Here is a sample output from running the tests:


                                When requesting values at 1000 millisecond intervals for time frame with data available:

                                Time(ms) getting values for point with one value per second: 59,0059

                                Time(ms) getting values for point with one value per minute: 845,0845


                                When requesting values at 100 millisecond intervals for time frame with data available:

                                Time(ms) getting values for point with one value per second: 575,0575

                                Time(ms) getting values for point with one value per minute: 8353,8353


                                When requesting values at 100 millisecond intervals after last recorded point :

                                Time(ms) getting values for point with one value per second: 4182,4182

                                Time(ms) getting values for point with one value per minute: 4115,4115


                                When requesting values at 10 second intervals after last recorded point :

                                Time(ms) getting values for point with one value per second: 843,0843

                                Time(ms) getting values for point with one value per minute: 614,0614

                                1 of 1 people found this helpful
                                  • Re: PiPoint.RecordedValuesAtTimes performance

                                    Hello Sigmund,


                                    Within the Jive editor you should see 'Use advanced editor' at the top right hand side of the frame. Within the advanced editor you will find an Icon >> that includes the functions for Syntax highlighting.

                                    I took the freedom to format your code. Related to the issue itself, I can only imagine that the RecordedValuesAtTimes algorithm is not optimized to operate with sub second timestamps.

                                    1 of 1 people found this helpful
                                    • Re: PiPoint.RecordedValuesAtTimes performance

                                      Hi Sigmund,

                                      Thanks for reporting this issue. I am able to reproduce it with PI DA 2016 R2, where the bottleneck seems to be in the server, by looking at the RPC call elapse time (using AFGetTrace).

                                      I have forwarded this to the PI DA team, and they're looking into it. I will give an update once I hear back from them.

                                      • Re: PiPoint.RecordedValuesAtTimes performance

                                        Hi Sigmund,

                                        To give you an update, we have found the root cause of the issue in PI Data Archive, where there is performance degradation when querying for unflushed events which are between last archived event and snapshot. It only affects the tag with an event every minute, because there are only 60 values, therefore, this is not enough to force a flush to disk (events remain in the cache). PI Data Archive team is still looking into this and hope to find a resolution in the upcoming release.


                                        Just an additional note for future reference, due to the current PI DA design:

                                        Querying data that covers snapshot would typically have worse performance than if querying only covers archive. In your case, where the request times cover all the way to the snapshot time (also, with AFRetrievalMode.AtOrAfter), point_A (with less dense data, 1 event per minute), with such query, will hit snapshot more times than point_B (with denser data, 1 per second). So, it'd be expected in this case that point_A to be less performant that point_B.

                                        However, with the unflushed events issue, the performance differences become magnitudes larger.


                                        Note that these findings are in sync with Gavin's analysis.

                                        1 of 1 people found this helpful