Hello,

I'm experiencing massive performance issues in tester runs that I didn't experience with the previous builds of JForex.
I've logged the processing times of onTick() as well as the total processing time for each hour through setting timers in onBar().

I've found that the processing times of one tick is in average and depending on the strategy I use between 1 to 5ms and does not greatly change over the course of a longer run. Depending on the number of ticks the total onTick-processing time for one hour of historic data is between 2 and 10s.

What brings the performance issue is, that over the course of the run the time used outside of onTick-processing increases dramatically! While in the beginning of a run, there is only minor additional processing time used by JForex beside (outside) of onTick() after about 4 months into a run, the non onTick-processing times for one hour of historic data have increased to more than 40-60 seconds!

The following data is from a tester run that I've started yesterday at 10am for the period of 1.1.2009 to 12.12.2009 on GBP/USD.
The run is now, nearly 1 day later, processing the 27th of March 2009 (!).

The below logging snippet shows, that the processing of the 18:00 hourly candlestick for March 27th took 1min 11sec (between 07:50:27 and 07:51:38), while the onTick-processing of the 2544ticks only took 5.9s!



Over the weekend when there are no ticks to process or charts to update, every hour takes more than 40 seconds without any onTick-call!



All processing of my strategy that is run here is in onTick, so nothing from the strategy's side should slow the client down.

It's not possible at this moment to efficiently test strategies over a longer period as it takes days to process a year's time of data.
The behaviour also shows when selecting periods other than "Ticks" for the tester run!

Could you please have a look into this?

Any fixes, thoughts, tips and help to get the tester efficiently working again
are very much appreciated!
Best RR.

I've now deactivated all drawings in IChart to see if the performance slowdown is related to the number and/or position of chart-objects.
But still without any custom-charting the performance goes drastically down over time.

Any feedback on a status of the analysis of this problem
would be very much appreciated.

Best, RR.

Dear support team,

the time used up by JForex between onTick(..) and onBar(..) processings is constantly getting longer and longer throughout a run.
From the below logging snippets you can see, that while in the beginning of the run 75% of the processing time was used in onTick about 4 months into the run it it was less that 10%. The "overhead" time used up outside onBar() and onTick() is at this point ways longer than the actual processing time of the strategy.

At the same time the memory values shown in the Java memory heap do not dramatically increase over time and are ways below the limit. On top, my cache-data is in a RAM-disk, so access is very fast. And it's also not the size of logfiles etc., that causes this performance problem.

So the central questions are:
* What is JForex doing outside of onBar/onTick() and what of this overhead processing does cost that much time?
* And why is it building up over time?
* Is there anything I can do or check on my side to prevent the tester runs to slow down over time?

I didn't experience this behaviour with earlier versions of JForex. Only with the latest builds. I've tried with the demo and the live login. Both current versions exhibit the same behaviour.

Any feedback on this behaviour is very much appreciated!
Thanks a lot and best,
RR.

Dear support team,

may I ask you for a short feedback on this issue?
Did you already have time to look into this behaviour?
Any ideas of what might be the cause?
Do you have any suggestions how we could possibly address this issue from our side?

Looking forward to hearing from you.
Best regards,
RR.

Hello,
Could you provide us some example strategy that reproduce this problem? Using empty or the strategy that creates some orders every 5mins doesn't reproduce the problem

Thanks for your reply!

The strategy itself runs in a larger embedded system that in total comprises more than 40000 loc...
It's not something I could quickly post...
There is one main call to the strategy code from onTick(..) and very minor parts from onBar(..).
At the time the control is back in onTick/onBar there is no additional thread left that's waiting for anything.

The time is only building up outside the custom strategy code, i.e. between the end of onTick(..) and the next onTick(..)-call. The processing time of the strategy code itself stays fairly constant over time.

We do not know what it is, we only can exclude the following suspects:
A. The memory heap is ok and not at its limit.
B. It has not to do with the visual charting, as it also slows down when the charting is switched off.
C. It's not the logging to files (changing the logging levels do not have a significant impact on the slowing down)
D. We have run several strategies that vary in the number of indicators used as well as the processing steps, etc. and all show the same behaviour.

The question is what function in between the onTick-calls might use more and more time?
Is there a logging we could switch on on our side to get further information about the process on DK-side?

Thanks a lot and best, RR.

In general tester has the following logical steps:
1. Get the next tick or bar, pass it to all the subsystems like IHistory interface that should return last tick if called from strategy.
2. Call the onTick or onBar method with this new tick or bar
3. Recalculate account data (equity etc)
4. Process the calls from the user like submit order or change the amount, call the onMessage method when necessary
5. Process conditional orders (limit orders, takeprofit stoploss, placebid placeoffer)
6. Recalculate account data if necessary (changes was made)
7. Check margin cut/call situations, open cutting orders if necessary
8. Execute tasks submitted through IContext.executeTask
9. get back to 1.

As you can see there is many steps besides onTick onBar methods. They are necessary to emulate server work, but i don't see what could take more and more time through the strategy progress. The only idea so far is - it can be possible if you have more and more orders as the strategy runs

With all strategies we are backtesting at the moment there is
a) only one trade at a time and
b) they only run on one currency pair.
c) All stop loss and take profit processing is dynamically done by the strategy code (called from within onTick) and only the open and close orders are sent to the server. So there is actually very little communication with the server.
d) In the strategies we are testing at the moment the filter is set to WEEKENDS or ALL_FLATS. Could the filter setting influence the performance? Are the flats calculated on the fly?

What strikes me is that even during the weekends when there are no ticks the time to process one hour (measured in onBar) lasts longer and longer over the course of a run and can get up to 50 seconds and above (for ONE_HOUR of empty tick data!).

Are there maybe functions active to check the data consistency during the run? Some time ago I did submit bug reports regarding data inconcistencies (missing tick data for several hours during a weekday...) and curve server errors. These errors do not show up anymore. Could it be that something got changed in this part that could lead to a "performance leak"?

I'm just thinking aloud:
1) If the strategy would be slow from the beginning onwards one could think of timeouts etc. the process is running into.
2) If the complete processing would slow down, it could be a resource problem, but the time to process 1 tick stays more or less constant while the "overhead" time is building up...
3) So it seems to me that there is some loop, etc. that processes more elements, checks more data etc. over time.

I'm running 2 instances with visual charting on OR 3 instances without visual charting on parallel at all times on a quadcore with a CPU usage of about 90%. I've tried multiple instances logged in on the same account as well as in different accounts, but with the same behaviour.

Would it be possible to activate a performance logging on your processing steps (only in the historical tester engine of course) that outputs the times e.g. per day on a higher logging level to see what step(s) are causing the slowdown?

Best, RR.

are you using getBars or some indicator? or where do you set this filter?

Does the problem happen with visual testing? Does it happen without visual testing?

Yes, we are using IHistory.getBars(..) as well as IIndicator.*(..) calls and yes, the filters are set in the funciton calls. (We use a global Filter parameter that is set from configuration properties at the beginning of the run and this filter parameter is referenced in the calls...).


The problem occurs with both, visual testing on AND off.

And it is always the time between the end of onTick(..) and the start of a new onTick(..)-processing that is getting longer and longer and is dragging performance down.

Hello,

have you been able to make any progress working on this issue?

I now did leave a run on that I started on Jan 4th at 8pm with a date range from 2009.01.05 to 2009.12.31.

This run is now, 3.5 days later(!) processing 2009.06.29. One hour of data with ticks now takes 4 minutes to process with onTick processing still using only a few seconds of it. And one hour of tickless data over the weekend now takes more than 3 minutes to process!

I've included a logging that remembers the longest time found in between onTick-calls per hour. I wanted to see, if the max time happens at the same time of the hour and how much time does elapse at maximum between onTick-calls.

From the logging snippet shown below, you can see that the max time onTick waited for a next tick varied between 3.7 and 4.9 sec, while the time between the 2nd last and the last tick of the hour varied between 1ms and 1sec. This shows that this inbetween time is varying quite a bit and is not constant.



After cancelling this run and restarting it from 2009.06.29 onwards, the processing times for the same hours as above are (for example June 29th at 4am) 4.9s as compared to above 241.2s! You also can see that the onTick-times only slightly increased.



Here's additional information that might or might not be helpful for you:
a) The memory heap shows values that constantly cycle from around 180 to 480 to 280 and back to 180. One such cycle needs about 1 second.
b) The connection status shows "connected" with the green icon constantly blinking.
c) at the times shown in the logging snippet above there were no trades

I'm sure you can understand that with these times efficient backtesting is not possible for us at the moment.
I hope we can find a solution very soon as we fall more and more behind schedule with our testing plans.

Could you please give us a short status from your side and if you have already been successful identifying the issue? And please let us know, if we can do anything on our side to support you finding the cause of the performance dragdown.

Thanks a lot and best,
RR.

we have some optimizations ready in next version (will be on demo next week). I couldn't reproduce slowing effect though, calling getBars, indicators, creating orders doesn't slow down the strategy execution

great, thanks a lot for your message!

Would it be possible for the next Demo build to include timers for your main processing steps that you listed in a previous post that measure the times used for an hour of tickdata and issue debug messages in case the time used by far exceeds a reasonable time (e.g. 60s or 90s/hour of historical tickdata)? This way we could quickly what step does cause the performance drain.

Best, RR.

New version is on demo, check your strategy. Btw, just got it in mind... press Get Data before you run your strategy. If you don't have the data, it will be downloaded while your strategy runs. This will slow down execution process significantly.

Hi,

no, the processing times outside of onTick and onBar still increase.
I have a run on that now has processed 5 weeks of tick data and the times outside of onTick already increased from 20% to 55% of the total processing times, with visual mode turned OFF.
I'll let the run go a bit further and compare processing times with the old version, but the issue is still there.

Is there an option to switch on additional loggings?

Thanks a lot for your help!
Best,
RR.

Hi,

sorry to say, but the issue has not gotten better.
After now 2 months of datafeed processing, the time it takes to process everything outside onTick(..) and onBar(..) now takes 85% of the processing time.



BTW: yes, all data has already been downloaded to the cache before the start of the tester run. (This is also true for all logging snippets posted previously in this thread)

What can we do to track this issue down?

Thanks for your help, RR.

Please, do the following:
1. Try to run some simple strategy, this for example:

package jforex;

import java.util.*;

import com.dukascopy.api.*;

public class LimitOrderEvery5Mins implements IStrategy {
   private IEngine engine;
   private IConsole console;
   private IHistory history;
   private IContext context;
   private IIndicators indicators;
   private IUserInterface userInterface;
    
    private long ticks;
    private long time;
    private long realTime;
    private IOrder order;
   
   public void onStart(IContext context) throws JFException {
      this.engine = context.getEngine();
      this.console = context.getConsole();
      this.history = context.getHistory();
      this.context = context;
      this.indicators = context.getIndicators();
      this.userInterface = context.getUserInterface();
   }

   public void onAccount(IAccount account) throws JFException {
   }

   public void onMessage(IMessage message) throws JFException {
   }

   public void onStop() throws JFException {
   }

   public void onTick(Instrument instrument, ITick tick) throws JFException {
        ++ticks;
        if (realTime == 0) {
            realTime = System.currentTimeMillis();
            time = tick.getTime();
        }
        if (time + 24 * 60 * 60 * 1000 < tick.getTime()) {
            long currentTime = System.currentTimeMillis();
            long millis = currentTime - realTime;
            long hours = millis / (60 * 60 * 1000);
            millis -= hours * 60 * 60 * 1000;
            long mins = millis / (60 * 1000);
            millis -= mins * 60 * 1000;
            long secs = millis / 1000;
            millis -= secs * 1000;

            double millisecondsPerTick = ((double) (currentTime - realTime)) / ticks;
            
            console.getOut().println(ticks + " ticks processed in " + hours + "h " + mins + "m " + secs + "s " + millis + "milliseconds. MSPT - " + millisecondsPerTick);
            
            realTime = System.currentTimeMillis();
            time = tick.getTime();
            ticks = 0;
        }
        if (order == null || order.getCreationTime() + 5 * 60 * 1000 < tick.getTime()) {
            if (order != null && (order.getState() == IOrder.State.OPENED || order.getState() == IOrder.State.FILLED)) {
                do {
                    order.close();
                    long safetyTimer = history.getTimeOfLastTick(instrument);
                    while (order.getState() != IOrder.State.CLOSED && order.getState() != IOrder.State.CANCELED && safetyTimer + 10000 > history.getTimeOfLastTick(instrument)) {
                        order.waitForUpdate(1000);
                    }
                } while (order.getState() == IOrder.State.OPENED || order.getState() == IOrder.State.FILLED);
            }
            order = engine.submitOrder("order", instrument, IEngine.OrderCommand.BUYLIMIT, 0.001, tick.getAsk() - 2 * instrument.getPipValue());
        }
        //history.getBars(instrument, Period.TEN_SECS, OfferSide.BID, Filter.ALL_FLATS, 5, history.getTimeForNBarsBack(Period.TEN_SECS, tick.getTime(), 3), 1);
        //indicators.sma(instrument, Period.TEN_SECS, OfferSide.BID, IIndicators.AppliedPrice.CLOSE, 5, Filter.ALL_FLATS, 3, tick.getTime(), 0);
   }
   
    public void onBar(Instrument instrument, Period period, IBar askBar, IBar bidBar) throws JFException {
    }
}

Try also running it with two lines uncommented
2. If the problem is not reproducible with this strategy, then look into your strategy and try to find what calls make this slow down, start removing logic from it part by part until problem disappears. Or go from other side, try to add in this simple strategy calls that you make in your strategy one by one until problem will show itself

Hi,

sorry for not coming back to you earlier.
I meanwhile had some other things on the table, but am now fully working on this issue again.

I did run your sample code and it runs fast and without significant delays.
I've then switched off various code-branches of our strategy-engine, that is called from within onTick.
For all the tests I've switched off invocation of and communication with external processes (switched off all file handling such as logging to files, serialization to files, etc., email/sms-messaging and database access) and did not use any visual charting.

When processing our complete strategy code but supressing all orders and all charting-actions from being submitted to your engine (so nothing is left to process on DK's side) I experience the following:
a) There is still a significant increase of processing times outside of onTick/onBar.
-> at the beginning of the run, these times are around: 0.1s/hour of tick data
-> after 4 month into the run, the times are up to: 5.0s/hour
-> after 12 month into the run, the times are up to: 12.0s/hour
(while the number of ticks vary over time, the times given above where taken from hours that have about the same number of ticks.)

b) when allowing all orders and charting calls to be passed on to DK, the processing times outside onTick/onBar do increase ways more compared to the figures shown above in a) (see my previous postings - the processing outside onTick/onBar then increases in time up to several minutes per hour of tick data!)

c) when switching off the update of our module that handles all indicator-calls and comparisons, times outside onTick/onBar decrease and stay more or less constant in longer runs. This module does a lot of calls to IIndicators and IHistory and caches a lot of data in classes, list- and map-objects.

d) in all runs, the processing times that I can measure for our own code do NOT increase but stay constant. The performance leak happens between the exiting of an onTick-code and the call of the next onTick.

d) when running your sample code and increasing the number of indicator calls (by calling the history.getbars and indicators.sma in a loop) I don't see siginficant increases of time.

I'm a bit lost here and would need your help.

My conclusion so far is:
1) Something in our code seems to slow down processing significantly on your side, while the processing times in our own code do not increase over time.
2) The performance leak has 2 measurable sources, that are involved: submitting orders and/or charting actions and retrieving IIndicator and IHistory data. Our meta indicator module retrieves, combines and rates indicator data, performs calculations etc. and caches data in a class structure with a lot of list and map objects.
3) As times do not increase in the processing of this meta indicator engine, it must influence something in your code.

Here is where I need your help.
In the above tests, I've looped IHistory.getbars and IIndicators.sma and did not experience a performance leak. In my code I'm using a lot more indicators. My next questions are:
A) Do you cache anything on your side related to indicator/history calls? Do you perform clean-up's of cached data that might take time?

B) Are there any indicators in your library you would rate as very resource intensive?

C) Are there any resources/objects on your side related to indicator/history-code that are not fully destroyed after the calls?

D) Even with your test code I've experienced a memory leak when repeatedly compiling code/running a strategy/cancelling the run. (This leak has been around for a long time and got a lot better with bugfixing but is still there). Do you know the cause of this leak and could it in any way also be related to this performance issue?

D) How could the structure/size/resource allocation of my code possibly influence something in your threads?
Are there any "clean-up"-procedures, etc. on your side that could possibly work on resources of my code?

E) Are there any threads on your side that could possible wait for something or loop through something with an ever increasing number of elements?

F) Would you be willing to consider implementing timers on your side for the tester engine in order to further collect information of where this problem comes from?

G) Do you have any other ideas of how to track this issue down?

Thanks a lot for your help and excellent support!
Looking forward to hearing from you,
Best, RR.

A) Do you cache anything on your side related to indicator/history calls? Do you perform clean-up's of cached data that might take time?
Yes we do. About 300 latest candles are held in memory and are updated every time new tick arrives. If request to calculate indicator arrives, we take this data instead reading it from file system.
There is no need to clean up this data. It's only 300 candles for every instrument/period/offerside combination that you used to calculate indicators

B) Are there any indicators in your library you would rate as very resource intensive?
I personally didn't test any indicators for efficiency, but it should take constant time anyway

C) Are there any resources/objects on your side related to indicator/history-code that are not fully destroyed after the calls?
No, there are not. This would lead to OutOfMemoryException, not to slowdown

D) Even with your test code I've experienced a memory leak when repeatedly compiling code/running a strategy/cancelling the run. (This leak has been around for a long time and got a lot better with bugfixing but is still there). Do you know the cause of this leak and could it in any way also be related to this performance issue?
I can imagine some leaks when you are using visual testing. I don't know of any leaks right now, this need closer investigation

D) How could the structure/size/resource allocation of my code possibly influence something in your threads?
Are there any "clean-up"-procedures, etc. on your side that could possibly work on resources of my code?
We call onStop method and if it doesn't exist for some time, we kill strategy thread with Thread.stop() method. If you strategy was creating some other threads or opened files or any other resources that must be closed, then you must close it in onStop method

E) Are there any threads on your side that could possible wait for something or loop through something with an ever increasing number of elements?
No, there are not such a threads, or I don't know of any.

F) Would you be willing to consider implementing timers on your side for the tester engine in order to further collect information of where this problem comes from?
This would require providing separate version and direct communication with the client. It's possible, but is a bit complicated

G) Do you have any other ideas of how to track this issue down?
No, no ideas

thanks a lot for your reply!

>>>
F) Would you be willing to consider implementing timers on your side for the tester engine in order to further collect information of where this problem comes from?
This would require providing separate version and direct communication with the client. It's possible, but is a bit complicated

G) Do you have any other ideas of how to track this issue down?
No, no ideas
<<<

As this is a major issue for us, I would very much appreciate if we could try to track down the issue with a separate version and a direct communication then.

Could you send me an email to the address registered with this user profile to get the communication going?

Thanks a lot!
RR.