Skip to content
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

Do not use pause detector for CommandLatencyCollector by default #1995

Closed
sinrimin opened this issue Feb 8, 2022 · 1 comment
Closed

Do not use pause detector for CommandLatencyCollector by default #1995

sinrimin opened this issue Feb 8, 2022 · 1 comment
Labels
type: enhancement A general enhancement
Milestone

Comments

@sinrimin
Copy link
Contributor

sinrimin commented Feb 8, 2022

Bug Report

I found that DefaultCommandLatencyCollector uses LatencyUtils.SimplePauseDetector by default, but SimplePauseDetector doesn't work as expected when pause occurs. Please try the test code below.

Test Code

@RunWith(Parameterized.class)
public class TestLatencyStats {
    private final long LOOP_TOTAL = 10000000;
    private final boolean usePauseDetector;

    public TestLatencyStats(final boolean usePauseDetector) {
        this.usePauseDetector = usePauseDetector;
    }

    @Parameterized.Parameters(name = "{index}: test LatencyStats with use SimplePauseDetector({0})")
    public static Collection<Boolean> data() {
        return Arrays.asList(true, false);
    }

    class Runner implements Runnable {
        final LatencyStats stats;

        Runner() {

            if (usePauseDetector) {
                SimplePauseDetector simplePauseDetector = new SimplePauseDetector(10_000_000L, 10_000_000L, 3);
                LatencyStats.setDefaultPauseDetector(simplePauseDetector);
            } else {
                LatencyStats.setDefaultPauseDetector(new PauseDetector() {
                });
            }
            stats = new LatencyStats();
        }

        @Override
        public void run() {
            stats.recordLatency(100_000_000);
        }
    }

    @Test
    public void test() {
        final ExecutorService executorService = Executors.newSingleThreadExecutor();
        final Runner runner = new Runner();

        for (int ndx = 0; ndx < LOOP_TOTAL; ndx++) executorService.submit(runner);
        try {
            executorService.shutdown();
            executorService.awaitTermination(30, TimeUnit.SECONDS);
        } catch (InterruptedException ex) {
        }

        runner.stats.getIntervalHistogram().
                outputPercentileDistribution(System.out, 1_000_000.0);
    }
}

Expected behavior/code

[0: test LatencyStats with use SimplePauseDetector(true)]
       Value     Percentile TotalCount 1/(1-Percentile)

        0.00 0.000000000000          1           1.00
      100.14 0.100000000000   10652383           1.11
      100.14 0.200000000000   10652383           1.25
      100.14 0.300000000000   10652383           1.43
      100.14 0.400000000000   10652383           1.67
      100.14 0.500000000000   10652383           2.00
      100.14 0.550000000000   10652383           2.22
      100.14 0.600000000000   10652383           2.50
      100.14 0.650000000000   10652383           2.86
      100.14 0.700000000000   10652383           3.33
      167.77 0.750000000000   10982557           4.00
      265.29 0.775000000000   11346730           4.44
      364.90 0.800000000000   11718537           5.00
      461.37 0.825000000000   12078601           5.71
      562.04 0.850000000000   12454320           6.67
      658.51 0.875000000000   12814385           8.00
      708.84 0.887500000000   13002245           8.89
      759.17 0.900000000000   13190105          10.00
      805.31 0.912500000000   13362310          11.43
      855.64 0.925000000000   13550169          13.33
      905.97 0.937500000000   13738029          16.00
      931.14 0.943750000000   13831959          17.78
      952.11 0.950000000000   13910233          20.00
      977.27 0.956250000000   14004164          22.86
     1002.44 0.962500000000   14098093          26.67
     1027.60 0.968750000000   14192023          32.00
     1040.19 0.971875000000   14238988          35.56
     1052.77 0.975000000000   14285954          40.00
     1065.35 0.978125000000   14332919          45.71
     1082.13 0.981250000000   14395538          53.33
     1090.52 0.984375000000   14426848          64.00
     1098.91 0.985937500000   14458158          71.11
     1098.91 0.987500000000   14458158          80.00
     1107.30 0.989062500000   14489468          91.43
     1115.68 0.990625000000   14520778         106.67
     1124.07 0.992187500000   14552088         128.00
     1124.07 0.992968750000   14552088         142.22
     1124.07 0.993750000000   14552088         160.00
     1132.46 0.994531250000   14583398         182.86
     1132.46 0.995312500000   14583398         213.33
     1132.46 0.996093750000   14583398         256.00
     1140.85 0.996484375000   14614708         284.44
     1140.85 0.996875000000   14614708         320.00
     1140.85 0.997265625000   14614708         365.71
     1140.85 0.997656250000   14614708         426.67
     1140.85 0.998046875000   14614708         512.00
     1149.24 0.998242187500   14639730         568.89
     1149.24 0.998437500000   14639730         640.00
     1149.24 0.998632812500   14639730         731.43
     1149.24 0.998828125000   14639730         853.33
     1149.24 0.999023437500   14639730        1024.00
     1149.24 0.999121093750   14639730        1137.78
     1149.24 0.999218750000   14639730        1280.00
     1149.24 0.999316406250   14639730        1462.86
     1149.24 0.999414062500   14639730        1706.67
     1149.24 0.999511718750   14639730        2048.00
     1149.24 0.999560546875   14639730        2275.56
     1149.24 0.999609375000   14639730        2560.00
     1149.24 0.999658203125   14639730        2925.71
     1149.24 0.999707031250   14639730        3413.33
     1149.24 0.999755859375   14639730        4096.00
     1149.24 0.999780273438   14639730        4551.11
     1149.24 0.999804687500   14639730        5120.00
     1149.24 0.999829101563   14639730        5851.43
     1149.24 0.999853515625   14639730        6826.67
     1149.24 0.999877929688   14639730        8192.00
     1149.24 0.999890136719   14639730        9102.22
     1149.24 0.999902343750   14639730       10240.00
     1149.24 0.999914550781   14639730       11702.86
     1149.24 0.999926757813   14639730       13653.33
     1149.24 0.999938964844   14639730       16384.00
     1149.24 0.999945068359   14639730       18204.44
     1216.35 0.999951171875   14639803       20480.00
     1291.85 0.999957275391   14639886       23405.71
     1375.73 0.999963378906   14639978       27306.67
     1459.62 0.999969482422   14640070       32768.00
     1501.56 0.999972534180   14640115       36408.89
     1585.45 0.999975585938   14640154       40960.00
     1686.11 0.999978637695   14640197       46811.43
     1795.16 0.999981689453   14640242       54613.33
     1904.21 0.999984741211   14640288       65536.00
     1954.55 0.999986267090   14640309       72817.78
     2013.27 0.999987792969   14640334       81920.00
     2063.60 0.999989318848   14640355       93622.86
     2113.93 0.999990844727   14640376      109226.67
     2181.04 0.999992370605   14640404      131072.00
     2197.82 0.999993133545   14640411      145635.56
     2231.37 0.999993896484   14640425      163840.00
     2248.15 0.999994659424   14640432      187245.71
     2281.70 0.999995422363   14640446      218453.33
     2315.26 0.999996185303   14640460      262144.00
     2315.26 0.999996566772   14640460      291271.11
     2332.03 0.999996948242   14640467      327680.00
     2348.81 0.999997329712   14640474      374491.43
     2365.59 0.999997711182   14640481      436906.67
     2382.36 0.999998092651   14640488      524288.00
     2382.36 0.999998283386   14640488      582542.22
     2382.36 0.999998474121   14640488      655360.00
     2399.14 0.999998664856   14640495      748982.86
     2399.14 0.999998855591   14640495      873813.33
     2415.92 0.999999046326   14640502     1048576.00
     2415.92 0.999999141693   14640502     1165084.44
     2415.92 0.999999237061   14640502     1310720.00
     2415.92 0.999999332428   14640502     1497965.71
     2415.92 0.999999427795   14640502     1747626.67
     2432.70 0.999999523163   14640509     2097152.00
     2432.70 1.000000000000   14640509
#[Mean    =       237.73, StdDeviation   =       281.08]
#[Max     =      2432.70, Total count    =     14640509]
#[Buckets =           26, SubBuckets     =          256]

[1: test LatencyStats with use SimplePauseDetector(false)]
       Value     Percentile TotalCount 1/(1-Percentile)

      100.14 0.000000000000   10000000           1.00
      100.14 1.000000000000   10000000
#[Mean    =        99.88, StdDeviation   =         0.00]
#[Max     =       100.14, Total count    =     10000000]
#[Buckets =           26, SubBuckets     =          256]

Possible Solution

Do not use SimplePauseDetector by default.

The micrometer has a similar problem, and since 1.0.10, 1.1.4, and 1.2.0 has used NoPauseDetector by default.
Pause Detection contributes to count when it should just contribute to total time.

@mp911de
Copy link
Collaborator

mp911de commented Feb 10, 2022

Thanks a lot for the detailed investigation. Would you like to submit a pull request to switch to NoPauseDetector? Using NoPauseDetector would allow to greatly simplify the code because we have specific code to delay the startup of SimplePauseDetector and to shut it down properly.

@mp911de mp911de added the type: task A general task label Feb 10, 2022
sinrimin added a commit to sinrimin/lettuce-core that referenced this issue Feb 11, 2022
@mp911de mp911de linked a pull request Feb 25, 2022 that will close this issue
@mp911de mp911de added this to the 6.1.7 milestone Feb 25, 2022
@mp911de mp911de added type: enhancement A general enhancement and removed type: task A general task labels Feb 25, 2022
@mp911de mp911de changed the title Pause Detection does not work as expected Do not use pause detector for CommandLatencyCollector by default Feb 25, 2022
mp911de pushed a commit that referenced this issue Feb 25, 2022
mp911de added a commit that referenced this issue Feb 25, 2022
Lazily create NoPauseDetector and ensure immediate shutdown of the pause thread. Add since tags.

Original pull request: #2005.
mp911de pushed a commit that referenced this issue Feb 25, 2022
mp911de added a commit that referenced this issue Feb 25, 2022
Lazily create NoPauseDetector and ensure immediate shutdown of the pause thread. Add since tags.

Original pull request: #2005.
@mp911de mp911de closed this as completed Feb 25, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type: enhancement A general enhancement
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants