[C++][Parquet] Non-dictionary BinaryArray reads from Parquet format have slowed down since 0.11.x

[asfimport]

In doing some benchmarking, I have found that binary reads seem to be slower from Arrow 0.11.1 to master branch. It would be a good idea to do some basic profiling to see where we might improve our memory allocation strategy (or whatever the bottleneck turns out to be)

Reporter: Wes McKinney / @wesm

Original Issue Attachments:

• 20190903_parquet_benchmark.py
• 20190903_parquet_read_perf.png

PRs and other links:

• GitHub Pull Request #5268
• GitHub Pull Request #5297

_{Note: This issue was originally created as ARROW-6417. Please see the migration documentation for further details.}

[asfimport]

Wes McKinney / @wesm:
I updated the results plot to use gcc 8.3 in both v0.11.1 and master branch as of 9/2/2019

[asfimport]

Wes McKinney / @wesm:
The dreaded \_\_memmove_avx_unaligned_erms has showed up again. I'll have a poke at this to see what could be done

 

+   60.85%     0.01%  python   libparquet.so.15.0.0                               [.] parquet::internal::TypedRecordReader<parquet::PhysicalType<(parquet::Type::ty▒
+   58.16%     0.00%  python   libparquet.so.15.0.0                               [.] parquet::internal::ByteArrayChunkedRecordReader::ReadValuesSpaced            ▒
+   57.54%     0.00%  python   libparquet.so.15.0.0                               [.] parquet::PlainByteArrayDecoder::DecodeArrow                                  ▒
+   57.52%     5.57%  python   libparquet.so.15.0.0                               [.] parquet::PlainByteArrayDecoder::DecodeArrow<arrow::internal::ChunkedBinaryBui▒
+   49.99%     4.80%  python   libparquet.so.15.0.0                               [.] arrow::internal::ChunkedBinaryBuilder::Append                                ▒
+   44.66%     9.74%  python   libarrow.so.15.0.0                                 [.] arrow::BaseBinaryBuilder<arrow::BinaryType>::Append                          ▒
+   30.62%     9.64%  python   libarrow.so.15.0.0                                 [.] arrow::BufferBuilder::Append                                                 ▒
+   23.51%    10.91%  python   libc-2.27.so                                       [.] __memmove_avx_unaligned_erms                                                 ▒
+   21.23%     0.00%  python   [unknown]                                          [.] 0xffffffffffffffff                                                           ▒
+   18.58%     0.01%  python   libparquet.so.15.0.0                               [.] parquet::ColumnReaderImplBase<parquet::PhysicalType<(parquet::Type::type)6> >▒
+   18.45%    14.80%  python   libsnappy.so.1.1.7                                 [.] snappy::RawUncompress                                                        ▒
+   18.42%     0.02%  python   libparquet.so.15.0.0                               [.] parquet::SerializedPageReader::NextPage                                      ▒
+   18.27%     0.00%  python   libarrow.so.15.0.0                                 [.] arrow::util::SnappyCodec::Decompress                                         ▒
+   18.27%     0.00%  python   libarrow.so.15.0.0                                 [.] arrow::util::SnappyCodec::Decompress                                         ▒
+   18.27%     0.00%  python   libsnappy.so.1.1.7                                 [.] snappy::RawUncompress                                                        ▒
+   14.99%     0.00%  python   libarrow.so.15.0.0                                 [.] arrow::PoolBuffer::Resize                                                    ▒
+   14.99%     0.00%  python   libarrow.so.15.0.0                                 [.] arrow::PoolBuffer::Reserve                                                   ▒
+   14.99%     0.00%  python   libarrow.so.15.0.0                                 [.] arrow::DefaultMemoryPool::Reallocate                                         ▒
+   14.98%     0.01%  python   libarrow.so.15.0.0                                 [.] je_arrow_rallocx                                                             ▒
+   14.97%     0.00%  python   libarrow.so.15.0.0                                 [.] je_arrow_private_je_arena_ralloc                                             ▒
+   14.96%     0.00%  python   libarrow.so.15.0.0                                 [.] je_arrow_private_je_large_ralloc                                             ▒
+   14.64%     0.00%  python   libarrow.so.15.0.0                                 [.] arrow::BufferBuilder::Resize                                                 ▒
+   12.82%    12.82%  python   [unknown]                                          [k] 0xffffffff98e00a67                                                           ▒
+   11.74%     3.73%  python   libarrow.so.15.0.0                                 [.] arrow::BaseBinaryBuilder<arrow::BinaryType>::AppendNextOffset  

[asfimport]

Wes McKinney / @wesm:
OK, I think to make things faster we need to be more careful about pre-allocating with BinaryBuilder and calling BaseBinaryBuilder<T>::UnsafeAppend instead of Append. It's a bit tricky because we have ChunkedBinaryBuilder in the mix, so we may have to manage the creation of chunks in the Parquet value decoder. I think this is worth the effort given how much of a hot path this is for reading Parquet files. I'll spend a little time on it tomorrow

[asfimport]

Wes McKinney / @wesm:
So on closer inspection, in v0.11.1 we weren't yet handling chunked binary reads at all, so the comparison is not really apples to oranges. v0.12.x was the first release series to include chunking support, so could be the more appropriate comparison.

This performance issue is really vexing. We also changed jemalloc versions between 0.12.x and 0.15.x so I wonder if the allocator version could be impacting performance

[asfimport]

Wes McKinney / @wesm:
Further down the rabbit hole

0.12.1 perf profile

   - parquet::arrow::FileReader::Impl::ReadSchemaField                                                                                                             
      - 66.24% parquet::arrow::ColumnReader::NextBatch                                                                                                             
         - parquet::arrow::PrimitiveImpl::NextBatch                                                                                                                
            - 66.23% parquet::internal::RecordReader::ReadRecords                                                                                                  
               - 41.51% parquet::internal::TypedRecordReader<parquet::DataType<(parquet::Type::type)6> >::ReadRecordData                                           
                  - 38.62% parquet::internal::TypedRecordReader<parquet::DataType<(parquet::Type::type)6> >::ReadValuesSpaced                                      
                     - 26.97% arrow::internal::ChunkedBinaryBuilder::Append                                                                                        
                        - 24.06% arrow::BinaryBuilder::Append                                                                                                      
                           + 12.78% arrow::BufferBuilder::Append                                                                                                   
                             1.99% arrow::ArrayBuilder::Reserve                                                                                                    
                             1.16% arrow::BufferBuilder::Append@plt                                                                                                
                             0.52% arrow::ArrayBuilder::Reserve@plt                                                                                                                          0.57% arrow::BinaryBuilder::Append@plt                                                                                                   
                     + 8.34% parquet::Decoder<parquet::DataType<(parquet::Type::type)6> >::DecodeSpaced                                                            
                       0.53% arrow::internal::ChunkedBinaryBuilder::Append@plt                                                                                     
                    2.02% parquet::internal::DefinitionLevelsToBitmap                                                                                              
                  + 0.86% parquet::internal::RecordReader::RecordReaderImpl::ReserveValues                                                                        
               + 24.31% parquet::internal::TypedRecordReader<parquet::DataType<(parquet::Type::type)6> >::ReadNewPage 

master / my ARROW-6417 branch

   - 74.04% parquet::internal::TypedRecordReader<parquet::PhysicalType<(parquet::Type::type)6> >::ReadRecords                                                      
      - 49.00% parquet::internal::TypedRecordReader<parquet::PhysicalType<(parquet::Type::type)6> >::ReadRecordData                                                
         - 45.82% parquet::internal::ByteArrayChunkedRecordReader::ReadValuesSpaced                                                                                
            - 45.19% parquet::PlainByteArrayDecoder::DecodeArrow                                                                                                   
               + 20.92% arrow::BaseBinaryBuilder<arrow::BinaryType>::ReserveData                                                                                   
                 7.61% __memmove_avx_unaligned_erms                                                                                                                
               + 2.59% arrow::BaseBinaryBuilder<arrow::BinaryType>::Resize                                                                                         
                 0.77% memcpy@plt                                                                                                                                  
            + 0.63% parquet::DictByteArrayDecoderImpl::DecodeArrow                                                                                                 
           2.09% parquet::internal::DefinitionLevelsToBitmap                                                                                                       
         + 1.07% parquet::internal::TypedRecordReader<parquet::PhysicalType<(parquet::Type::type)6> >::ReserveValues                                               
      + 24.32% parquet::SerializedPageReader::NextPage                                                                                                             

Furthermore, jemalloc is show up as taking a lot more time on 5.2.x versus the older version we had before

master

+   24.59%     0.00%  python   libarrow.so.15.0.0                                 [.] je_arrow_rallocx                                                             
+   24.58%     0.00%  python   libarrow.so.15.0.0                                 [.] je_arrow_private_je_arena_ralloc                                             
+   24.57%     0.00%  python   libarrow.so.15.0.0                                 [.] je_arrow_private_je_large_ralloc                                             

0.12.1

+    8.30%     0.01%  python   libarrow.so.12.1.0                                 [.] je_arrow_rallocx                                                             
+    8.28%     0.01%  python   libarrow.so.12.1.0                                 [.] je_arrow_private_je_arena_ralloc 

So it seems like the difference in jemalloc versions may be accounting for some of the performance difference. The other thing that strikes me is that the UBSAN changes (SafeLoadAs) are likely introducing performance degradation because the Parquet BYTE_ARRAY encoding results in mostly unaligned lengths.

cc @pitrou [~emkornfield@gmail.com] for any thoughts...

[asfimport]

Antoine Pitrou / @pitrou:
Have you tried to measure the same jemalloc version for the two Arrow versions (or, conversely, the two jemalloc versions for the same Arrow version)?

[asfimport]

Wes McKinney / @wesm:
I will try that next. I'm going to merge my current patch in the meantime and leave this JIRA open

[asfimport]

Micah Kornfield / @emkornfield:
For SafeLoadAs, you could try changing the implementation to dereference instead of memcpy, which should be equivalent to the old code (assuming it is getting inlined correctly).  IIRC, we saw very comparable numbers for the existing parquet benchmarks when I made those changes. 

[asfimport]

Wes McKinney / @wesm:
OK, it appears that the jemalloc version is causing the perf difference

current master branch with vendored jemalloc version (4.something with patches)

$ python 20190903_parquet_benchmark.py 
dense-random 100000
({'case': 'read-dense-random-single-thread'}, 0.6065331888198853)

master with jemalloc 5.2.0

$ python 20190903_parquet_benchmark.py 
dense-random 100000
({'case': 'read-dense-random-single-thread'}, 1.2143790817260742)

To reproduce these results yourself

• Get the old jemalloc tarball from here https://github.com/apache/arrow/tree/maint-0.12.x/cpp/thirdparty/jemalloc

• Set $ARROW_JEMALLOC_URL to the path of that before building

• Use this branch which has the old EP configuration https://github.com/wesm/arrow/tree/use-old-jemalloc

  Here's the benchmark script that I'm running above

  https://gist.github.com/wesm/7e5ae1d41981cfdd20415faf71e5f57e

  I'm interested if other benchmarks are affected or if this is a peculiarity of this particular benchmark

[asfimport]

Wes McKinney / @wesm:
The benchmark results in arrow-builder-benchmark are pretty damning...

master

---------------------------------------------------------------------------
Benchmark                                    Time           CPU Iterations
---------------------------------------------------------------------------
BufferBuilderTinyWrites/real_time    264925407 ns  264925189 ns          2    966.31MB/s
BufferBuilderSmallWrites/real_time   178721490 ns  178720664 ns          4   1.39882GB/s
BufferBuilderLargeWrites/real_time   192722520 ns  192720335 ns          4   1.29027GB/s
BuildBooleanArrayNoNulls              61622618 ns   61620052 ns         11   4.05712GB/s
BuildIntArrayNoNulls                 159926782 ns  159919611 ns          4   1.56329GB/s
BuildAdaptiveIntNoNulls               34141484 ns   34141072 ns         20   7.32256GB/s
BuildAdaptiveIntNoNullsScalarAppend  118671966 ns  118669726 ns          6   2.10669GB/s
BuildBinaryArray                     646172067 ns  646165509 ns          1   396.183MB/s
BuildChunkedBinaryArray              629538527 ns  629517882 ns          1    406.66MB/s
BuildFixedSizeBinaryArray            319843478 ns  319421997 ns          2   801.448MB/s
BuildDecimalArray                    613258571 ns  613249404 ns          1   834.897MB/s
BuildInt64DictionaryArrayRandom      265489567 ns  265479003 ns          3   964.295MB/s
BuildInt64DictionaryArraySequential  256461735 ns  256454103 ns          3   998.229MB/s
BuildInt64DictionaryArraySimilar     436497455 ns  436496161 ns          2   586.489MB/s
BuildStringDictionaryArray           737468427 ns  737429710 ns          1   463.142MB/s
ArrayDataConstructDestruct               38895 ns      38895 ns      18067

master with the older jemalloc

---------------------------------------------------------------------------
Benchmark                                    Time           CPU Iterations
---------------------------------------------------------------------------
BufferBuilderTinyWrites/real_time    139816022 ns  139814056 ns          5   1.78806GB/s
BufferBuilderSmallWrites/real_time    35215592 ns   35214766 ns         19   7.09912GB/s
BufferBuilderLargeWrites/real_time    32460612 ns   32456001 ns         21   7.66046GB/s
BuildBooleanArrayNoNulls              33690068 ns   33688611 ns         21   7.42091GB/s
BuildIntArrayNoNulls                  49988970 ns   49987507 ns         14   5.00125GB/s
BuildAdaptiveIntNoNulls               23878665 ns   23876703 ns         29   10.4705GB/s
BuildAdaptiveIntNoNullsScalarAppend  116140426 ns  116137665 ns          6   2.15262GB/s
BuildBinaryArray                     593711307 ns  593699295 ns          1   431.195MB/s
BuildChunkedBinaryArray              538185849 ns  538185876 ns          1   475.672MB/s
BuildFixedSizeBinaryArray            218638403 ns  218631191 ns          3   1.14348GB/s
BuildDecimalArray                    294477232 ns  294474155 ns          2   1.69794GB/s
BuildInt64DictionaryArrayRandom      248790745 ns  248788395 ns          3   1028.99MB/s
BuildInt64DictionaryArraySequential  238954386 ns  238949356 ns          3   1071.36MB/s
BuildInt64DictionaryArraySimilar     422484600 ns  422471016 ns          2   605.959MB/s
BuildStringDictionaryArray           716507144 ns  716487471 ns          1    476.68MB/s
ArrayDataConstructDestruct               38406 ns      38406 ns      18229

So it seems that performance in realloc-heavy workloads is degraded

[asfimport]

Wes McKinney / @wesm:
I opened an issue with jemalloc to see if we're doing something wrong jemalloc/jemalloc#1621

[asfimport]

Antoine Pitrou / @pitrou:
Wow that's massive.

Re SafeLoadAs, I'm with Micah: it shouldn't make a difference on a x86 CPU with a decent compiler. Worth checking anyway.

[asfimport]

Antoine Pitrou / @pitrou:
FTR, similar issues with jemalloc seem to have happened in the past, I wonder if it's a regression:
jemalloc/jemalloc#335
jemalloc/jemalloc#126

[asfimport]

Wes McKinney / @wesm:
After reverting the jemalloc version, the benchmarks show that master is faster than v0.12.1, which is certainly what I was hoping for after all the work we put in refactoring stuff the last few months. So the SafeLoadAs issue is no longer a concern

[asfimport]

Wes McKinney / @wesm:
This was fixed in 0.15.0 by the jemalloc toolchain work and other optimizations