The Reference Stream is taking a long time to iterate through

[awrigh11]

Describe the bug
The Reference Stream created in GCRun.getReferences() appears to be taking longer to iterate through than the Reference iterator that was implemented in 1.10.

Our GC cycles are taking at least 3x longer on accumulo 2.1.1 than they did in 1.10. We performed a jstack on the gc cycle and virtually all the time was spent iterating through the stream.

Note: The GC cycles are taking 3x when candidate batching does not occur. When candidate batching occurs GC cycle times increase by X more times (where X is the number of batches) (For example: when we perform 4 batches, the GC cycles were about 12x longer than they were in 1.10)
Versions (OS, Maven, Java, and others, as appropriate):

• Affected version(s) of this project: 2.1.1

To Reproduce
Run a Jstack on a GC cycle on a cluster

Expected behavior
The GC cycle times would not signifcantly increase between versions

[ctubbsii]

When candidate batching occurs GC cycle times increase by X more times (where X is the number of batches) (For example: when we perform 4 batches, the GC cycles were about 12x longer than they were in 1.10)

I think that part is expected... and would have occurred with batching in 1.10 using a JVM with less memory. In 2.1, batch sizes are determined explicitly through configuration. We found this to be much more reliable (and a substantially simpler implementation) than the auto-batching based on available memory, which did not always work well if the JVM was resizing or during some Java GC cycles. The configurable batch sizes should allow more control over the size of the batches you want to process, and you can tune your JVM memory accordingly. This issue and the user's requirement to choose their own batch size was specifically called out with its own paragraph in the 2.1.0 release notes.

[awrigh11]

I think that part is expected... and would have occurred with batching in 1.10 using a JVM with less memory. In 2.1, batch sizes are determined explicitly through configuration. We found this to be much more reliable (and a substantially simpler implementation) than the auto-batching based on available memory, which did not always work well if the JVM was resizing or during some Java GC cycles. The configurable batch sizes should allow more control over the size of the batches you want to process, and you can tune your JVM memory accordingly. This issue and the user's requirement to choose their own batch size was specifically called out with its own paragraph in the 2.1.0 release notes.

Yeah I would agree. I just wanted to be clear that our 3x slow down was not related to batching.

[ctubbsii]

@awrigh11 I wonder if #3501 / #3502 will completely address your issue, or if we'll need to try to do something else as well with the stream iterating.

[awrigh11]

@awrigh11 I wonder if #3501 / #3502 will completely address your issue, or if we'll need to try to do something else as well with the stream iterating.

I wonder the same thing as well. The timing metrics referenced in those PRs do look promising.

[dlmarion]

I asked @dtspence to update https://github.com/dtspence/accumulo-jmh-test with the following:

1. you are creating 3 tablet servers, one test table, and 10,000 files. However, you are not adding splits to the test table, so it's very possible that there is only one metadata table tablet. You may want to consider setting the metadata table split size to something low so that it splits and adding splits to the test table. Maybe 100 splits with 100 files each?
2. if you make the number of files configurable, then you can run several times with different inputs (e.g. 100, 1000, 10000) to see what the curve looks like.
3. I created a non-streaming implementation of the getReferences() method (below). Can you also add a test for this method?

  public Iterator<Reference> getReferenceIter() {

  final IteratorChain<Reference> iterChain = new IteratorChain<>();
  
  Iterable<TabletMetadata> tmIter = null;
  if (level == Ample.DataLevel.ROOT) {
    tmIter = Collections.singleton(context.getAmple().readTablet(RootTable.EXTENT, DIR, FILES, SCANS));
  } else {
    tmIter = TabletsMetadata.builder(context).scanTable(level.metaTable())
        .checkConsistency().fetch(DIR, FILES, SCANS).build();
  }

  tmIter.forEach(tabletMetadata -> {
    int fileCount = tabletMetadata.getFiles().size() + tabletMetadata.getScans().size() + ((tabletMetadata.getDirName() == null) ? 0 : 1);
    List<Reference> referencedFiles = new ArrayList<>(fileCount);
    tabletMetadata.getFiles().forEach(stf -> 
      referencedFiles.add(new ReferenceFile(tabletMetadata.getTableId(), stf.getMetaUpdateDelete())));
    tabletMetadata.getScans().forEach(stf -> 
      referencedFiles.add(new ReferenceFile(tabletMetadata.getTableId(), stf.getMetaUpdateDelete())));
    if (tabletMetadata.getDirName() != null) {
      referencedFiles.add(new ReferenceDirectory(tabletMetadata.getTableId(), tabletMetadata.getDirName()));
    }
    iterChain.addIterator(referencedFiles.iterator());
  });
  
  List<ReferenceFile> ssrefs = context.getAmple().getScanServerFileReferences()
      .map(sfr -> new ReferenceFile(sfr.getTableId(), sfr.getPathStr())).collect(Collectors.toList());
  iterChain.addIterator(ssrefs.iterator());
  
  return iterChain;
  
}

[keith-turner]

I created a non-streaming implementation of the getReferences() method (below). Can you also add a test for this method?

That implementation may buffer all of the references in memory which we would like to avoid.

[dtspence]

The results below use an updated tests branch implementing 1) multiple metadata-splits, 2) parameterized splits/files, and 3) multiple table splits. The tests show a few different implementations (including the original 2.1.1 baseline and version 1.10.3). I had been using #3501 for benchmarking during the week and included below. The profiler comparision on the updated 2.1.2-SNAPSHOT (latest) suggested there is some overhead with Path() and validateFileName() due to regex evaluation, which does not appear in #3501.

The parameterized splits/files affected the per operation output and resulted in an overall execution time. The per-operation metric was relocated to the rfile/op (in the data below).

The logic is currently on two separate branches (kept separate to avoid any impact to testing late last week):
https://github.com/dtspence/accumulo-jmh-test/tree/gc-test-update
https://github.com/dtspence/accumulo-jmh-test/tree/accumulo-1.10

---

Accumulo 1.10: The following details Accumulo 1.10.3 performance of getReferenceIterator() method. The test extracted the method located in SimpleGarbageCollector and executed in isolation. The test used multiple metadata tablets per t-server and included the other changes from the gc-test-update branch.

Location of method extracted:
https://github.com/apache/accumulo/blob/1.10/server/gc/src/main/java/org/apache/accumulo/gc/SimpleGarbageCollector.java#L323

Benchmark                                                   (splitsRfile)  Mode  Cnt    Score     Error  Units
GarbageCollectorPerformanceIT.benchmarkReferences                   1,100  avgt    3    0.471 ±   0.143  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences:rfile/op          1,100  avgt    3    0.005 ±   0.001  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences                  10,100  avgt    3    2.936 ±   0.482  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences:rfile/op         10,100  avgt    3    0.003 ±   0.001  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences                 100,100  avgt    3   39.415 ±  11.400  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences:rfile/op        100,100  avgt    3    0.004 ±   0.001  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences                1000,100  avgt    3  357.505 ± 231.943  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences:rfile/op       1000,100  avgt    3    0.004 ±   0.002  ms/op

---

Accumulo 2.1.1: The following is a baseline test of 2.1.1.

Benchmark                                                   (splitsRfile)  Mode  Cnt     Score     Error  Units
GarbageCollectorPerformanceIT.benchmarkReferences                   1,100  avgt    3     2.377 ±   0.726  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences:rfile/op          1,100  avgt    3     0.024 ±   0.007  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences                  10,100  avgt    3    16.781 ±   8.778  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences:rfile/op         10,100  avgt    3     0.017 ±   0.009  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences                 100,100  avgt    3   137.649 ±  67.144  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences:rfile/op        100,100  avgt    3     0.014 ±   0.007  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences                1000,100  avgt    3  1207.793 ± 528.944  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences:rfile/op       1000,100  avgt    3     0.012 ±   0.005  ms/op

PR 3501: The logic in #3501 resulted in the following times.

Benchmark                                                   (splitsRfile)  Mode  Cnt    Score    Error  Units
GarbageCollectorPerformanceIT.benchmarkReferences                   1,100  avgt    3    1.241 ±  0.559  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences:rfile/op          1,100  avgt    3    0.012 ±  0.006  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences                  10,100  avgt    3    5.304 ±  3.251  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences:rfile/op         10,100  avgt    3    0.005 ±  0.003  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences                 100,100  avgt    3   30.570 ± 11.835  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences:rfile/op        100,100  avgt    3    0.003 ±  0.001  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences                1000,100  avgt    3  201.415 ± 92.688  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences:rfile/op       1000,100  avgt    3    0.002 ±  0.001  ms/op

Accumulo 2.1.2-SNAPSHOT: The most recent GC changes from 2.1.2-SNAPSHOT. The removal of the getParent() calls helped a lot to improve performance. The profiler showed a couple of calls 1) Path.init() and 2) validateFileName() which contained additional regex calls.

Benchmark                                                   (splitsRfile)  Mode  Cnt    Score     Error  Units
GarbageCollectorPerformanceIT.benchmarkReferences                   1,100  avgt    3    1.665 ±   0.211  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences:rfile/op          1,100  avgt    3    0.017 ±   0.002  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences                  10,100  avgt    3   10.139 ±  16.299  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences:rfile/op         10,100  avgt    3    0.010 ±   0.016  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences                 100,100  avgt    3   62.035 ±  24.129  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences:rfile/op        100,100  avgt    3    0.006 ±   0.002  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences                1000,100  avgt    3  521.994 ± 228.079  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences:rfile/op       1000,100  avgt    3    0.005 ±   0.002  ms/op

Accumulo 2.1.2-SNAPSHOT (with Path(URI) and validateFileName()): The following is based on the GC changes (from 2.1.2-SNAPSHOT) and makes a minor change to use the Path(URI) constructor (mentioned previously), avoiding a regex call. It also used the alternate validateFileName() described below.

Reference:

accumulo/core/src/main/java/org/apache/accumulo/core/metadata/StoredTabletFile.java

Line 47 in 260fde4

super(new Path(metadataEntry));

Benchmark                                                   (splitsRfile)  Mode  Cnt    Score     Error  Units
GarbageCollectorPerformanceIT.benchmarkReferences                   1,100  avgt    3    1.346 ±   0.402  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences:rfile/op          1,100  avgt    3    0.013 ±   0.004  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences                  10,100  avgt    3    6.318 ±   2.323  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences:rfile/op         10,100  avgt    3    0.006 ±   0.002  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences                 100,100  avgt    3   36.814 ±   2.904  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences:rfile/op        100,100  avgt    3    0.004 ±   0.001  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences                1000,100  avgt    3  244.694 ± 140.063  ms/op
GarbageCollectorPerformanceIT.benchmarkReferences:rfile/op       1000,100  avgt    3    0.002 ±   0.001  ms/op

Validate FileName: Created an additional benchmark to experiment with a non-regex version of the check. I looked through PR comments and could not find if it was specifically discussed.

Baseline (w/regex):
Benchmark                                              Mode  Cnt  Score   Error  Units
ValidationUtilPerformanceIT.benchmarkValidateFileName  avgt    3  5.359 ± 0.572  ms/op

Character comparison test:
Benchmark                                              Mode  Cnt  Score   Error  Units
ValidationUtilPerformanceIT.benchmarkValidateFileName  avgt    3  0.216 ± 0.047  ms/op

    public static void validateFileName(String fileName) {
        Objects.requireNonNull(fileName);
        for (int i = 0; i < fileName.length(); i++) {
            final char ch = fileName.charAt(i);
            if (!(Character.isLetterOrDigit(ch) || ch == '-' || ch == '.' || ch == '_')) {
                throw new IllegalArgumentException(
                        "Provided filename (" + fileName + ") contains invalid characters.");
            }
        }
    }

[dlmarion]

@dtspence - do you want to put up a PR against the 2.1 branch with the Path(URI) and validateFileName changes? While not as fast as #3501, it's close and faster than 1.10.

[dtspence]

@dtspence - do you want to put up a PR against the 2.1 branch with the Path(URI) and validateFileName changes? While not as fast as #3501, it's close and faster than 1.10.

Yes, I will put up a PR with changes.

[keith-turner]

I created #3543 which contains a small change from #3501 that was unrelated to the lazy evaluation.