Skip to content

Backpressure and gc #2001

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
davidmoten opened this issue Dec 17, 2014 · 11 comments
Closed

Backpressure and gc #2001

davidmoten opened this issue Dec 17, 2014 · 11 comments

Comments

@davidmoten
Copy link
Collaborator

Further to the discussion in #1941 I'm processing records at about 50,000 messages/s using code like this with java 1.7u72.

Observable<String> filenames = ...

filename
    // batch the filenames so we don't overload merge
   .window(availableProcessors - 2)
   // get positions for each window
  .concatMap(filenames->filenames.flatMap(
           f -> positions(f).subscribeOn(Schedulers.computation()))
  .subscribe();

The positions are read from a file using backpressure enabled operators (no onBackpressureBuffer is in use) so everything goes nicely for a minute or two at which point a full GC is required. While the full GC is running the stream is still running full bore creating objects and consuming memory, so much so that by the time the full GC is finished, heap usage is so high that another GC is required and before you know it everything's hung due to GC not keeping up with object creation.

Any suggestions for how to induce backpressure when GC not keeping up?

@benjchristensen
Copy link
Member

The window operator consumes as fast as it can without backpressure: https://github.com/ReactiveX/RxJava/blob/1.x/src/main/java/rx/internal/operators/OperatorWindowWithSize.java#L92

This was originally thought to be the correct behavior for window, but since then we have debated it and think that the window(int size) variant should support backpressure and only the temporal variants should not.

The issue that you'll need solved for backpressure to work here is: #1828 Backpressure: Window by Size

@davidmoten
Copy link
Collaborator Author

I switched to using buffer and problem still happens (I assume buffer is backpressure enabled).

Observable<String> filenames = ...

filename
    // batch the filenames so we don't overload merge
   .buffer(availableProcessors - 2)
   .map(list -> Observable.from(list))
   // get positions for each window
  .concatMap(filenames->filenames.flatMap(
           f -> positions(f).subscribeOn(Schedulers.computation()))
  .subscribe();

@davidmoten
Copy link
Collaborator Author

I've tried these jvm args:

-XX:+UseConcMarkSweepGC -verbose:gc -XX:+ScavengeBeforeFullGC

and problem is delayed slightly but still happens. Overall GC is slower than object creation so I run out of memory and operators are none the wiser in terms of slowing down requests.

@benjchristensen
Copy link
Member

The buffer(int size) operator should support it. I confirmed in the code that it has an implementation to support backpressure: https://github.com/ReactiveX/RxJava/blob/1.x/src/main/java/rx/internal/operators/OperatorBufferWithSize.java

So now we look for bugs if this is not actually working.

This code seems to be functioning but I have not looked at memory yet. I want to confirm this is functioning correctly:

import java.util.List;

import rx.Observable;
import rx.schedulers.Schedulers;

public class BufferBackpressure {

    public static void main(String... args) {
        Observable.range(0, 10000000)
                .doOnRequest(r -> System.out.println("requested: " + r))
                .doOnNext(i -> System.out.println("raw emission: " + i))
                // batch the filenames so we don't overload merge
                .buffer(Runtime.getRuntime().availableProcessors() - 2)
                .map(list -> Observable.from(list))
                // get positions for each window
                .concatMap(filenames -> filenames.flatMap(f -> positions(f).subscribeOn(Schedulers.computation())))
                .toBlocking().forEach(System.out::println);
    }

    private static Observable<String> positions(int i) {
        return Observable.just(i).map(n -> {
            try {
                Thread.sleep(1000);
            } catch (Exception e) {
                e.printStackTrace();
            }
            return "Processed => " + n;
        });
    }
}

This emits the following which shows it is requesting the chunks correctly:

requested: 12
raw emission: 0
raw emission: 1
raw emission: 2
raw emission: 3
raw emission: 4
raw emission: 5
raw emission: 6
raw emission: 7
raw emission: 8
raw emission: 9
raw emission: 10
raw emission: 11
Processed => 2
Processed => 0
Processed => 1
Processed => 3
Processed => 4
Processed => 5
requested: 6
raw emission: 12
raw emission: 13
raw emission: 14
raw emission: 15
raw emission: 16
raw emission: 17
Processed => 6
Processed => 7
Processed => 8
Processed => 9
Processed => 10
Processed => 11
requested: 6
raw emission: 18
raw emission: 19
raw emission: 20
raw emission: 21
raw emission: 22
raw emission: 23
Processed => 16
Processed => 12
Processed => 13
Processed => 14
Processed => 15
Processed => 17
requested: 6
raw emission: 24
raw emission: 25
raw emission: 26
raw emission: 27
raw emission: 28
raw emission: 29
Processed => 21
Processed => 18
Processed => 19
Processed => 20
Processed => 22
Processed => 23
requested: 6
raw emission: 30
raw emission: 31
raw emission: 32
raw emission: 33
raw emission: 34
raw emission: 35
Processed => 29
Processed => 26
Processed => 24
Processed => 25
Processed => 27
Processed => 28
requested: 6
raw emission: 36
raw emission: 37
raw emission: 38
raw emission: 39
raw emission: 40
raw emission: 41
Processed => 34
Processed => 30
Processed => 31
Processed => 32
Processed => 33
Processed => 35
requested: 6
raw emission: 42
raw emission: 43
raw emission: 44
raw emission: 45
raw emission: 46
raw emission: 47
Processed => 38
Processed => 36
Processed => 37
Processed => 39
Processed => 40
Processed => 41
requested: 6

Is this what you see when running your version? The assumption here is that your Observable<String> is backpressure aware.

@davidmoten
Copy link
Collaborator Author

I think backpressure is working fine it's just that GC is not keeping up with object creation. Note that no objects are retained by this stream so GC should be able to clean up virtually everything given the opportunity. This is the log with mem usage (scroll right to see), messagePerSecond since start (not useful from line to line) and GC logging. By the last line the process has hung.

[GC 2848882K->173146K(2903040K), 0.0214670 secs]
2014-12-17 17:15:41.034  [RxComputationThreadPool-5] - count=1005000, msgPerSecond==55935.88245116046, usedMem=288MB, percentMax=3.9, max=7456MB
2014-12-17 17:15:41.099  [RxComputationThreadPool-6] - count=1010000, msgPerSecond==56008.42899129374, usedMem=509MB, percentMax=6.8, max=7456MB
2014-12-17 17:15:41.164  [RxComputationThreadPool-4] - count=1015000, msgPerSecond==56083.54514310974, usedMem=743MB, percentMax=10.0, max=7456MB
2014-12-17 17:15:41.227  [RxComputationThreadPool-4] - count=1020000, msgPerSecond==56167.40088105727, usedMem=978MB, percentMax=13.1, max=7456MB
2014-12-17 17:15:41.290  [RxComputationThreadPool-6] - count=1025000, msgPerSecond==56244.51273046532, usedMem=1199MB, percentMax=16.1, max=7456MB
2014-12-17 17:15:41.353  [RxComputationThreadPool-1] - count=1030000, msgPerSecond==56327.244886798646, usedMem=1420MB, percentMax=19.0, max=7456MB
2014-12-17 17:15:41.419  [RxComputationThreadPool-6] - count=1035000, msgPerSecond==56394.050019070455, usedMem=1628MB, percentMax=21.8, max=7456MB
2014-12-17 17:15:41.483  [RxComputationThreadPool-1] - count=1040000, msgPerSecond==56469.56616169843, usedMem=1849MB, percentMax=24.8, max=7456MB
2014-12-17 17:15:41.547  [RxComputationThreadPool-6] - count=1045000, msgPerSecond==56544.559277095395, usedMem=2056MB, percentMax=27.6, max=7456MB
2014-12-17 17:15:41.608  [RxComputationThreadPool-6] - count=1050000, msgPerSecond==56628.19544817172, usedMem=2277MB, percentMax=30.5, max=7456MB
2014-12-17 17:15:41.669  [RxComputationThreadPool-1] - count=1055000, msgPerSecond==56711.283126377464, usedMem=2498MB, percentMax=33.5, max=7456MB
2014-12-17 17:15:41.729  [RxComputationThreadPool-1] - count=1060000, msgPerSecond==56796.870813909874, usedMem=2705MB, percentMax=36.3, max=7456MB
2014-12-17 17:15:41.790  [RxComputationThreadPool-4] - count=1065000, msgPerSecond==56878.87203588977, usedMem=2926MB, percentMax=39.2, max=7456MB
[GC 2859098K->189210K(2875392K), 0.0317560 secs]
2014-12-17 17:15:41.884  [RxComputationThreadPool-4] - count=1070000, msgPerSecond==56860.452757997664, usedMem=412MB, percentMax=5.5, max=7456MB
2014-12-17 17:15:41.949  [RxComputationThreadPool-5] - count=1075000, msgPerSecond==56932.52833386294, usedMem=617MB, percentMax=8.3, max=7456MB
2014-12-17 17:15:42.010  [RxComputationThreadPool-1] - count=1080000, msgPerSecond==57010.13513513513, usedMem=836MB, percentMax=11.2, max=7456MB
2014-12-17 17:15:42.071  [RxComputationThreadPool-1] - count=1085000, msgPerSecond==57090.2394106814, usedMem=1041MB, percentMax=14.0, max=7456MB
2014-12-17 17:15:42.131  [RxComputationThreadPool-5] - count=1090000, msgPerSecond==57172.82979281406, usedMem=1259MB, percentMax=16.9, max=7456MB
2014-12-17 17:15:42.194  [RxComputationThreadPool-6] - count=1095000, msgPerSecond==57248.91514612851, usedMem=1478MB, percentMax=19.8, max=7456MB
2014-12-17 17:15:42.255  [RxComputationThreadPool-5] - count=1100000, msgPerSecond==57324.50883318568, usedMem=1710MB, percentMax=22.9, max=7456MB
2014-12-17 17:15:42.316  [RxComputationThreadPool-1] - count=1105000, msgPerSecond==57402.5974025974, usedMem=1929MB, percentMax=25.9, max=7456MB
2014-12-17 17:15:42.378  [RxComputationThreadPool-1] - count=1110000, msgPerSecond==57477.21623860812, usedMem=2148MB, percentMax=28.8, max=7456MB
2014-12-17 17:15:42.449  [RxComputationThreadPool-4] - count=1115000, msgPerSecond==57524.63498942372, usedMem=2352MB, percentMax=31.5, max=7456MB
2014-12-17 17:15:42.512  [RxComputationThreadPool-6] - count=1120000, msgPerSecond==57595.39236861051, usedMem=2585MB, percentMax=34.7, max=7456MB
2014-12-17 17:15:42.576  [RxComputationThreadPool-6] - count=1125000, msgPerSecond==57662.73705791902, usedMem=2817MB, percentMax=37.8, max=7456MB
[GC 2847514K->201498K(2889216K), 0.0237410 secs]
[Full GC 201498K->190244K(3030528K), 0.4395060 secs]
2014-12-17 17:15:43.105  [RxComputationThreadPool-1] - count=1130000, msgPerSecond==56390.03942312491, usedMem=304MB, percentMax=4.1, max=7456MB
2014-12-17 17:15:43.171  [RxComputationThreadPool-4] - count=1135000, msgPerSecond==56453.61850285999, usedMem=577MB, percentMax=7.7, max=7456MB
2014-12-17 17:15:43.236  [RxComputationThreadPool-5] - count=1140000, msgPerSecond==56522.38583965492, usedMem=782MB, percentMax=10.5, max=7456MB
2014-12-17 17:15:43.300  [RxComputationThreadPool-6] - count=1145000, msgPerSecond==56587.92132054957, usedMem=1001MB, percentMax=13.4, max=7456MB
2014-12-17 17:15:43.368  [RxComputationThreadPool-4] - count=1150000, msgPerSecond==56644.6655501921, usedMem=1233MB, percentMax=16.5, max=7456MB
2014-12-17 17:15:43.435  [RxComputationThreadPool-6] - count=1155000, msgPerSecond==56703.81462025627, usedMem=1452MB, percentMax=19.5, max=7456MB
2014-12-17 17:15:43.499  [RxComputationThreadPool-1] - count=1160000, msgPerSecond==56770.90980277003, usedMem=1684MB, percentMax=22.6, max=7456MB
2014-12-17 17:15:43.563  [RxComputationThreadPool-4] - count=1165000, msgPerSecond==56840.35909445745, usedMem=1903MB, percentMax=25.5, max=7456MB
2014-12-17 17:15:43.625  [RxComputationThreadPool-6] - count=1170000, msgPerSecond==56912.15098745014, usedMem=2121MB, percentMax=28.5, max=7456MB
2014-12-17 17:15:43.687  [RxComputationThreadPool-6] - count=1175000, msgPerSecond==56980.74778138791, usedMem=2340MB, percentMax=31.4, max=7456MB
2014-12-17 17:15:43.755  [RxComputationThreadPool-5] - count=1180000, msgPerSecond==57035.13944608246, usedMem=2572MB, percentMax=34.5, max=7456MB
2014-12-17 17:15:43.821  [RxComputationThreadPool-4] - count=1185000, msgPerSecond==57094.67598169116, usedMem=2805MB, percentMax=37.6, max=7456MB
[GC 2848548K->253339K(3001344K), 0.0191290 secs]
2014-12-17 17:15:43.946  [RxComputationThreadPool-5] - count=1190000, msgPerSecond==56992.337164750956, usedMem=787MB, percentMax=10.5, max=7456MB
2014-12-17 17:15:44.052  [RxComputationThreadPool-5] - count=1195000, msgPerSecond==56942.723720575625, usedMem=1561MB, percentMax=20.9, max=7456MB
2014-12-17 17:15:44.167  [RxComputationThreadPool-5] - count=1200000, msgPerSecond==56869.342685180796, usedMem=2411MB, percentMax=32.3, max=7456MB
[GC-- 2884012K->3253107K(3253760K), 0.4303220 secs]
[Full GC 3253107K->1942067K(3450368K), 3.4775630 secs]
2014-12-17 17:15:48.210  [RxComputationThreadPool-4] - count=1205000, msgPerSecond==47923.958001909006, usedMem=2448MB, percentMax=32.8, max=7456MB
[GC-- 3218641K->3896478K(3932160K), 0.4929570 secs]
[Full GC 3896478K->2778555K(4200960K), 1.7715600 secs]
2014-12-17 17:15:50.602  [RxComputationThreadPool-6] - count=1210000, msgPerSecond==43942.4753050552, usedMem=2935MB, percentMax=39.4, max=7456MB
2014-12-17 17:15:50.724  [RxComputationThreadPool-6] - count=1215000, msgPerSecond==43929.42367488611, usedMem=3884MB, percentMax=52.1, max=7456MB
[GC-- 3897282K->4531694K(4566528K), 0.4539290 secs]
[Full GC 4531694K->3496044K(4907520K), 2.1728480 secs]
2014-12-17 17:15:53.476  [RxComputationThreadPool-6] - count=1220000, msgPerSecond==40118.38211114765, usedMem=4378MB, percentMax=58.7, max=7456MB
[GC-- 4531538K->5555787K(5591552K), 0.7128820 secs]
[Full GC 5555787K->4166540K(6026240K), 2.3246170 secs]
2014-12-17 17:15:56.638  [RxComputationThreadPool-5] - count=1225000, msgPerSecond==36488.740617180985, usedMem=4954MB, percentMax=66.4, max=7456MB
[GC-- 5556603K->6351958K(6388224K), 0.5622330 secs]
[Full GC 6351958K->5063787K(6917120K), 2.9512940 secs]
2014-12-17 17:16:00.273  [RxComputationThreadPool-4] - count=1230000, msgPerSecond==33058.295482032954, usedMem=5386MB, percentMax=72.2, max=7456MB
2014-12-17 17:16:00.388  [RxComputationThreadPool-5] - count=1235000, msgPerSecond==33090.40244359895, usedMem=6360MB, percentMax=85.3, max=7456MB
[GC-- 6353036K->7142849K(7178752K), 0.5578060 secs]
[Full GC 7142849K->5905199K(7826432K), 3.2743840 secs]
2014-12-17 17:16:04.337  [RxComputationThreadPool-6] - count=1240000, msgPerSecond==30045.310266288678, usedMem=6901MB, percentMax=86.1, max=8014MB

@davidmoten
Copy link
Collaborator Author

Ah, my logging method (a custom Operator) was the culprit! Sorry to waste your time! It doesn't support backpressure.

@davidmoten
Copy link
Collaborator Author

Spoke too soon. Removed the logging calls and replaced with a simple doOnNext logging line and the problem still happened, just took longer.

@davidmoten
Copy link
Collaborator Author

I think it's on me to knock up a load test for you people to run. Might be tomorrow AEST though as it's home time.

@akarnokd
Copy link
Member

Memory profile would be great. Otherwise, my tip is on concatMap piling up filenames.

@davidmoten
Copy link
Collaborator Author

Hah, sorted it out. Twas a ring buffer size override that had been set to some enormous value as a test earlier. Sorry to have wasted your time, thanks for the responses.

@benjchristensen
Copy link
Member

Glad you found it! That’s a fun one :-)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants