Repository navigation
Large Memory and Speed performance regression from 2.5.3 to 2.6.3 #122
Description
Activity
More system information:
Ruby 3.2.2
Docker arm64 alpine linux on Mac OS X host via Docker DesktopRelated to #121 but more specific and I was able to find some data I can show you to reproduce it!
- changed the title
[-][RAILS ONLY] Large Memory and Speed performance regression from 2.5.3 to 2.6.3[/-][+][Docker ONLY] Large Memory and Speed performance regression from 2.5.3 to 2.6.3[/+]on Feb 21, 2024 Found that this is actually docker not rails. I spun up a fresh rails instance and wasn't producing it locally. Then, I used the rails default dockerfile modified to strip it back closer to essentials.
This is on arm64 architecture but I have the same problem in our production amd64 architecture docker images too.
# syntax = docker/dockerfile:1 # Make sure RUBY_VERSION matches the Ruby version in .ruby-version and Gemfile ARG RUBY_VERSION=3.2.2 FROM registry.docker.com/library/ruby:$RUBY_VERSION-slim as base # Rails app lives here WORKDIR /rails # Set production environment ENV BUNDLE_DEPLOYMENT="1" \ BUNDLE_PATH="/usr/local/bundle" \ BUNDLE_WITHOUT="development" # Throw-away build stage to reduce size of final image FROM base as build # Install packages needed to build gems RUN apt-get update -qq && \ apt-get install --no-install-recommends -y build-essential git libvips pkg-config # Copy application code COPY . . # Final stage for app image FROM base # Install packages needed for deployment RUN apt-get update -qq && \ apt-get install --no-install-recommends -y curl libsqlite3-0 libvips && \ rm -rf /var/lib/apt/lists /var/cache/apt/archives # Copy built artifacts: gems, application COPY --from=build /usr/local/bundle /usr/local/bundle COPY --from=build /rails /rails # Run and own only the runtime files as a non-root user for security RUN useradd rails --create-home --shell /bin/bash && \ chown -R rails:rails db log storage tmp USER rails:rails RUN gem install creek CMD ["bash"]
And built it
docker build .Then ran docker
docker run -it <image sha>Finally inside docker I ran irb:
rails@5058bc9c86b6:/rails$ irb
Inside irb I did:
irb(main):001:0> require 'creek' => true irb(main):003:0> time = Time.now; creek = Creek::Book.new('./performance-test.xlsx'); puts(Time.now - time); 7.558300586 => nil irb(main):004:0> time = Time.now; creek.sheets[0].simple_rows.map(&:inspect); puts(Time.now - time); 52.017292079 => nil
In a separate shell to the same docker container (
docker exec -it <container SHA (NOT image sha> bash) I did:rails@5058bc9c86b6:/rails$ ps -wef UID PID PPID C STIME TTY TIME CMD rails 1 0 0 17:07 pts/0 00:00:00 bash rails 18 1 26 17:08 pts/0 00:01:00 irb rails 20 0 0 17:12 pts/1 00:00:00 bash rails 27 20 0 17:12 pts/1 00:00:00 ps -wef rails@5058bc9c86b6:/rails$ grep -i vm /proc/18/status VmPeak: 3552164 kB VmSize: 3551392 kB VmLck: 0 kB VmPin: 0 kB VmHWM: 3408084 kB VmRSS: 3408084 kB VmData: 3462272 kB VmStk: 8188 kB VmExe: 4 kB VmLib: 12232 kB VmPTE: 6840 kB VmSwap: 0 kB
Note: I tried this in an amd_64 version of the same container and got the same result. 3GB RAM usage in 2.6.3, 800MB RAM in 2.5.3. Still on Mac OS X host though
Nevermind, I'm not used to Mac OS X and had trouble figuring out the peak memory usage.
Got
gtimeworking though and amd64 Mac OS X Sonoma 14.3.1 ruby 3.2.2 shows a similar though smaller effect.So this is not docker or rails specific, I just failed at figuring out peak memory usage on Mac and the speed didn't get way slower like it did in docker.
It is better locally at least. Only about 2.6x more memory not 5x.
lilithcarpenter@Liliths-MacBook-Pro tmp-rails % gtime -v irb irb(main):001> require 'creek' => true irb(main):002> Creek::VERSION => "2.6.3" irb(main):003> time = Time.now; creek = Creek::Book.new('./performance-test.xlsx'); puts(Time.now - time); 6.727392 irb(main):004> time = Time.now; creek.sheets[0].simple_rows.map(&:inspect); puts(Time.now - time); 32.480844 irb(main):005> Command being timed: "irb" User time (seconds): 36.39 System time (seconds): 2.42 Percent of CPU this job got: 21% Elapsed (wall clock) time (h:mm:ss or m:ss): 2:56.84 Average shared text size (kbytes): 0 Average unshared data size (kbytes): 0 Average stack size (kbytes): 0 Average total size (kbytes): 0 Maximum resident set size (kbytes): 1691680 Average resident set size (kbytes): 0 Major (requiring I/O) page faults: 14 Minor (reclaiming a frame) page faults: 654378 Voluntary context switches: 1737 Involuntary context switches: 20670 Swaps: 0 File system inputs: 0 File system outputs: 0 Socket messages sent: 0 Socket messages received: 0 Signals delivered: 0 Page size (bytes): 16384 Exit status: 0
lilithcarpenter@Liliths-MacBook-Pro tmp-rails % gtime -v irb irb(main):001> gem 'creek', '2.5.3' => true irb(main):002> require 'creek' => true irb(main):003> time = Time.now; creek = Creek::Book.new('./performance-test.xlsx'); puts(Time.now - time); 6.498211 irb(main):004> time = Time.now; creek.sheets[0].simple_rows.map(&:inspect); puts(Time.now - time); 27.670476 irb(main):005> Command being timed: "irb" User time (seconds): 34.16 System time (seconds): 0.57 Percent of CPU this job got: 53% Elapsed (wall clock) time (h:mm:ss or m:ss): 1:05.09 Average shared text size (kbytes): 0 Average unshared data size (kbytes): 0 Average stack size (kbytes): 0 Average total size (kbytes): 0 Maximum resident set size (kbytes): 647200 Average resident set size (kbytes): 0 Major (requiring I/O) page faults: 15 Minor (reclaiming a frame) page faults: 44136 Voluntary context switches: 3867 Involuntary context switches: 1967 Swaps: 0 File system inputs: 0 File system outputs: 0 Socket messages sent: 0 Socket messages received: 0 Signals delivered: 0 Page size (bytes): 16384 Exit status: 0
- changed the title
[-][Docker ONLY] Large Memory and Speed performance regression from 2.5.3 to 2.6.3[/-][+]Large Memory and Speed performance regression from 2.5.3 to 2.6.3[/+]on Feb 21, 2024 Identified commit 494ed05 as the culprit.
Version 2.6
irb(main):001> gem 'creek', '2.6.2' => true irb(main):002> require 'creek' => true irb(main):003> time = Time.now; creek = Creek::Book.new('performance-test.xlsx'); puts(Time.now - time); 6.848251 irb(main):004> time = Time.now; creek.sheets[0].simple_rows.map(&:inspect); puts(Time.now - time); 35.083837 irb(main):005> Command being timed: "irb" User time (seconds): 39.23 System time (seconds): 2.26 Percent of CPU this job got: 39% Elapsed (wall clock) time (h:mm:ss or m:ss): 1:45.88 Average shared text size (kbytes): 0 Average unshared data size (kbytes): 0 Average stack size (kbytes): 0 Average total size (kbytes): 0 Maximum resident set size (kbytes): 2344960 Average resident set size (kbytes): 0 Major (requiring I/O) page faults: 43 Minor (reclaiming a frame) page faults: 632327 Voluntary context switches: 797 Involuntary context switches: 13858 Swaps: 0 File system inputs: 0 File system outputs: 0 Socket messages sent: 0 Socket messages received: 0 Signals delivered: 0 Page size (bytes): 16384 Exit status: 0
Commit f8856ee
lilithcarpenter@Liliths-MacBook-Pro test-creek % gtime -v bundle exec irb irb(main):001:0> require 'creek' => true irb(main):002:0> time = Time.now; creek = Creek::Book.new('performance-test.xlsx'); puts(Time.now - time); 6.800597 => nil irb(main):003:0> time = Time.now; creek.sheets[0].simple_rows.map(&:inspect); puts(Time.now - time); 27.776927 => nil irb(main):004:0> Command being timed: "bundle exec irb" User time (seconds): 34.50 System time (seconds): 0.51 Percent of CPU this job got: 38% Elapsed (wall clock) time (h:mm:ss or m:ss): 1:30.84 Average shared text size (kbytes): 0 Average unshared data size (kbytes): 0 Average stack size (kbytes): 0 Average total size (kbytes): 0 Maximum resident set size (kbytes): 545728 Average resident set size (kbytes): 0 Major (requiring I/O) page faults: 29 Minor (reclaiming a frame) page faults: 49358 Voluntary context switches: 1595 Involuntary context switches: 1773 Swaps: 0 File system inputs: 0 File system outputs: 0 Socket messages sent: 0 Socket messages received: 0 Signals delivered: 0 Page size (bytes): 16384 Exit status: 0
Commit 494ed05
lilithcarpenter@Liliths-MacBook-Pro test-creek % gtime -v bundle exec irb irb(main):001:0> require 'creek' => true irb(main):002:0> time = Time.now; creek = Creek::Book.new('performance-test.xlsx'); puts(Time.now - time); 6.739267 => nil irb(main):003:0> time = Time.now; creek.sheets[0].simple_rows.map(&:inspect); puts(Time.now - time); 36.350612 => nil irb(main):004:0> Command being timed: "bundle exec irb" User time (seconds): 40.49 System time (seconds): 2.09 Percent of CPU this job got: 47% Elapsed (wall clock) time (h:mm:ss or m:ss): 1:28.87 Average shared text size (kbytes): 0 Average unshared data size (kbytes): 0 Average stack size (kbytes): 0 Average total size (kbytes): 0 Maximum resident set size (kbytes): 2022608 Average resident set size (kbytes): 0 Major (requiring I/O) page faults: 105 Minor (reclaiming a frame) page faults: 624585 Voluntary context switches: 747 Involuntary context switches: 20804 Swaps: 0 File system inputs: 0 File system outputs: 0 Socket messages sent: 0 Socket messages received: 0 Signals delivered: 0 Page size (bytes): 16384 Exit status: 0
The issue appears to be that calling
node.namespaces(which looks for namespaces on this node, and all the way up the document hierarchy) is hugely expensive within nokogiri, rather than strings within creek - although they could be improved.I've run a test using allocation_stats and mem GetProcessMem, reading 10k rows from a spreadsheet where I've observed this problem.
With the code as is results in a large number of hash allocations and lots of allocations within Nokogiri:
sourcefile sourceline class count gems/nokogiri-1.18.2-arm64-darwin/lib/nokogiri/xml/reader.rb 127 String 64407 gems/rubyzip-2.4.1/lib/zip/inflater.rb 19 String 42986 gems/nokogiri-1.18.2-arm64-darwin/lib/nokogiri/xml/reader.rb 127 Hash 33405 gems/rubyzip-2.4.1/lib/zip/ioextras/abstract_input_stream.rb 20 String 28666 gems/rubyzip-2.4.1/lib/zip/inflater.rb 19 Range 14330 creek/lib/creek/sheet.rb 127 String 11565 creek/lib/creek/sheet.rb 111 Hash 11565 creek/lib/creek/sheet.rb 132 Hash 10001 creek/lib/creek/sheet.rb 131 Hash 10001 If I change the code so that we only do that call if the node appears to have a prefix then the tests still pass, but the memory allocations go right down...
if prefix.empty? && node.prefix && node.namespaces.any?sourcefile sourceline class count gems/nokogiri-1.18.2-arm64-darwin/lib/nokogiri/xml/reader.rb 127 String 64407 gems/nokogiri-1.18.2-arm64-darwin/lib/nokogiri/xml/reader.rb 127 Hash 33405 creek/lib/creek/sheet.rb 127 String 11565 creek/lib/creek/sheet.rb 131 Hash 10001 creek/lib/creek/sheet.rb 132 Hash 10001 I'm not sure that would work with all spreadsheets that caused this change to be added, but it narrows down the causes.
Hello,
I've encountered the same issue and this commit was not enough to fix the issue in my case. I try to parse a 33MB xlsx file (500_000 rows) and it consumes 8GB. The culprit is the
node.namespacescall on every row as @transoceanic2000 mentionned.Indeed :
if prefix.empty? && node.prefix && node.namespaces.any?should work but from what I understand, nokogiri supply the node
namespace_uriandprefixso we should be able to skip all node that are not from our namespace of interest and grab the prefix used the first time a node in our namespace is seen. I think it's a bit easier to understand and doesn't require thenamespacese.g:
Nokogiri::XML::Reader.from_io(xml).each do |node| next unless node.namespace_uri == SPREADSHEETML_URI if prefix.empty? && node.prefix prefix = node.prefix name_row = "#{prefix}row" name_c = "#{prefix}c" name_v = "#{prefix}v" name_t = "#{prefix}t" endI'll do some tests when times allow it and supply an MR unless someone has a better idea.
Thanks.This should be fixed by #138 if it gets merged
We upgraded to rails 7.1.3 and at the same time I upgraded our version of creek from 2.5.3 to 2.6.3.
After deploying the new rails version, we noticed our memory usage going up significantly as well as our time to process spreadsheets.
I tested the two versions in irb isolation and saw no difference, with a slight improvement for 2.6.3. However, when in docker the difference is massive.(See #122 (comment), my testing methodology wasn't great for local Mac and the difference is less but still large. This is not just docker)
As you can see in the above, the problem appears to be the row generator. Also, the peak memory usage went from 709,000 KB to 3,852,000 KB, 5 times more memory!
Here is the spreadsheet I used for testing (a subset of chicago's public crime data) https://drive.usercontent.google.com/download?id=1zWiCRYCS7Vs9EPZyOqcKr-eT59F7w3dm&export=download (give it a minute to start downloading, google has to virus scan it first and it takes forever)