September 2023 - ruby-core - ml.ruby-lang.org

[ruby-core:113926] [Ruby master Bug#19735] Add support for UUID version 7
by nevans (Nicholas Evans) 19 Sep '23

19 Sep '23

Issue #19735 has been reported by nevans (Nicholas Evans). ---------------------------------------- Bug #19735: Add support for UUID version 7 https://bugs.ruby-lang.org/issues/19735 * Author: nevans (Nicholas Evans) * Status: Open * Priority: Normal * Backport: 3.0: UNKNOWN, 3.1: UNKNOWN, 3.2: UNKNOWN ---------------------------------------- Although the specification for UUIDv7 is still in draft, the UUIDv7 algorithm has been stable as the RFC progresses to completion. Version 7 UUIDs can be very useful, because they are lexographically sortable, which can improve e.g: database index locality. See section 6.10 of the draft specification for further explanation: https://www.ietf.org/archive/id/draft-ietf-uuidrev-rfc4122bis-06.html ```ruby require 'random/formatter' Random.uuid_v7 # => "0188ca50-fcc0-7881-b5c5-6d55cd8fc373" Random.uuid_v7 # => "0188ca51-0069-7304-be2e-0c3cd908789b" Random.uuid_v7 # => "0188ca51-04aa-7b57-a6ec-c49573412a9d" Random.uuid_v7 # => "0188ca51-0853-7979-ae37-485460e9f4f1" # or prng = Random.new prng.uuid_v7 # => "0188ca51-5e72-7950-a11d-def7ff977c98" ``` PR here: https://github.com/ruby/ruby/pull/7953 -- https://bugs.ruby-lang.org/

3 4

[ruby-core:114702] [Ruby master Feature#19874] Re-introduce heap sort by pinned count prior to GC compaction
by eightbitraptor (Matthew Valentine-House) 18 Sep '23

18 Sep '23

Issue #19874 has been reported by eightbitraptor (Matthew Valentine-House). ---------------------------------------- Feature #19874: Re-introduce heap sort by pinned count prior to GC compaction https://bugs.ruby-lang.org/issues/19874 * Author: eightbitraptor (Matthew Valentine-House) * Status: Open * Priority: Normal ---------------------------------------- See Github PR: [#8420](https://github.com/ruby/ruby/pull/8420) <hr /> ## Introduction In Ruby 2.7 compaction was originally introduced as an experimental feature. There was no auto-compaction, and compaction had to be manually triggered using `GC.compact`. See [this commit](https://github.com/ruby/ruby/commit/3ef4db15e95740839a0ed6d0224b2c9…. When this happened, at the start of compaction the heap was sorted so that pages containing the [most pinned slots were compacted into by default](https://github.com/ruby/ruby/commit/3ef4db15e95740839a0ed6d0224b2c…. This was important for compaction efficiency and copy on write friendliness as it prioritises filling pages that can't be free'd and emptying as many pages as possible. When `GC.auto_compact`, was introduced [in this commit](). This heap sorting mechanism was (unintentionally?) removed. This means that the heap is now unsorted when compacted and we're just compacting towards the lowest addresses from the higher ones. This PR re-introduces this feature: by default the heap will now be sorted by pinned object count prior to compaction. This will improve the CoW friendliness of compaction to aid the reforking work being carried out by byroot. ## Verifying the behaviour We used a test script to build a heap that would be laid out in a prescribed manner. with a predictable pinning pattern in order to test that pages with higher numbers of pinned objects are being filled first during compaction. Test script was as follows: ``` require 'fiddle' require 'objspace' objcount = 1_000_000 GC.disable list = [] # Create sparsely populated pages 32000.times do list << Object.new Object.new Object.new Object.new Object.new Object.new Object.new end # less sparsely populated pages 32000.times do list << Object.new Object.new Object.new Object.new end # densly populated pages 32000.times do list << Object.new Object.new end # packed pages 32000.times do list << Object.new end # Pin the set of objects and free the rest in order to create our controlled heap pinned = list.map { |x| Fiddle::Pinned.new(x) } GC.start # Dump the heap before compaction, this should contain lots of pages that contain # only pinned slots, in varying density patterns, followed by a solid chunk of # movable objects in the 40 byte size pool (these are the objects created by # `Fiddle::Pinned.new`). f = File.open("before.log", "w") ObjectSpace.dump_all(shapes: false, output: f) GC.compact GC.start puts `ps -o rss= -p #{$$}` # Dump the heap after compaction, this should show the same density pattern that we saw # in the previous dump, but this time the solid region of 40 byte objects should be compacted # into the pages with the most pinned objects first f = File.open("after.log", "w") ObjectSpace.dump_all(shapes: false, output: f) ``` ## Heap diagram before <img src="https://github.com/ruby/ruby/assets/31869/bffc0090-4790-477d-9476-bea5203fd…" width=400 /> This diagram shows heap pages vertically with the pinned object distribution pattern set up by the test script. ## Heap diagram after (master branch) <img src="https://github.com/ruby/ruby/assets/31869/3d3b8ff5-1625-4e05-b832-95d28f1a2…" width=400 /> This diagram shows the heap having been compacted without this patch. We can see that the heap has not been sorted by pages, and that movable objects (green) are being compacted into pages that contain fewer pinned objects, and leaving pages that contain lots of pinned objects sparsely populated. ## Heap diagram after (this branch) <img src="https://github.com/ruby/ruby/assets/31869/5ebdd282-b167-4ae4-b718-15fb095cf…" width=400 /> This diagram shows the heap having been compacted into pinned pages. This diagram shows pages sorted by their order in the `heap->pages` list. So will respect the sorting that happens during compaction. ## Benchmarking ### Compaction speed This plot shows mean and standard deviation of `GC.compact` time for 6 runs of the test script defined above on both this branch and master. Measured using `Benchmark.bm` <img src="https://github.com/ruby/ruby/assets/31869/fbe23946-08dd-4d8f-890c-5ab9be2dd…" width=640 /> Raw values are: | branch name | mean | std deviation | | ----------- | ------------ | ------------- | | this branch | 0.0125643333 | 0.0004797644 | | master | 0.0121891667 | 0.0008149953 | This data appears shows a 3% slowdown in GC compation times on this branch which is expected given the extra work required to sort the heap prior to compaction. However, given the sizeable overlap in the error bars we can conclude that this difference is not significant. ### Post compaction RSS We used a modified test script that created a heap with a lot of pinned slots at the end of the heap. The expected outcome is that if the heap remains unsorted, RSS will be higher because objects will be packed into the front of the heap, and then followed by sparsely populated pages of pinned objects. In a sorted heap, the objects will be packed in around the pages of pinned objects where possible allowing more empty pages to be free'd and RSS to be lower. Here is the test script used: ``` require 'fiddle' GC.disable list = [] 288000.times do Object.new end 36000.times do list << Object.new 50.times do Object.new end end pinned = list.map { |x| Fiddle::Pinned.new(x) } GC.start GC.compact puts `ps -o rss= -p #{$$}` ``` And here is the outcome: <img src="https://github.com/ruby/ruby/assets/31869/96716838-4d81-41fd-a91f-4704bed92…" width=640 /> Raw data: | branch name | mean | std deviation | | ----------- | ---------- | ------------- | | this branch | 92200.0000 | 332.9769 | | master | 93594.6667 | 188.9536 | We can see from this data that sorting the heap by pinned pages results in a 1.5% decrease in memory usage, and we can infer from the non-overlapping error bars that this is likely to be statistically significant. ## Conclusion Re-introducing heap sorting by pinned slots prior to compaction improves memory usage of a Ruby process by a statistically significant amount. It does this at a very slight, and likely insignificant performance penalty, which we believe to be acceptable given that GC compaction is currently a fairly major "stop the world" event that should only be done occasionally. For example, before forking. -- https://bugs.ruby-lang.org/

1 1

[ruby-core:114795] [Ruby master Bug#19888] Can't change binding of a Proc coerced from a Method
by waiting_for_dev 18 Sep '23

18 Sep '23

Issue #19888 has been reported by waiting_for_dev (Marc Busqué). ---------------------------------------- Bug #19888: Can't change binding of a Proc coerced from a Method https://bugs.ruby-lang.org/issues/19888 * Author: waiting_for_dev (Marc Busqué) * Status: Open * Priority: Normal * Backport: 3.0: UNKNOWN, 3.1: UNKNOWN, 3.2: UNKNOWN ---------------------------------------- `instance_exec` or `instance_eval` can execute a given `Proc` in the context of the receiver. However, that's not true when the `Proc` has been coerced from a `Method`. In that situation, the binding is always tied to the original instance. ```ruby class A def foo "from A" end end class B def foo "from B" end end A.new.instance_exec(&-> { foo }) # => from A A.new.instance_exec(&B.new.method(:foo)) # => from B A.new.instance_exec(&B.new.method(:foo).to_proc) # => from B ``` At first sight, that looks like a bug, as the transformation from `Method` to `Proc` is not complete. -- https://bugs.ruby-lang.org/

2 1

[ruby-core:114794] [Ruby master Bug#17263] Fiber context switch degrades with number of fibers, limit on number of fibers
by kjtsanaktsidis (KJ Tsanaktsidis) 18 Sep '23

18 Sep '23

Issue #17263 has been updated by kjtsanaktsidis (KJ Tsanaktsidis). File flamegraph_make_many_fibers.png added File cache_misses_vs_time.png added OK, so I spent way longer than I should have staring at this but I think I've worked out what's going on. There are a couple of separate fibers to unpick here (ba-dum tish); I'll look at making fibers and switching between fibers as separate issues. ## Making lots of fibers Firstly, the process of making lots of fibers (and switching to them for the first time) is kind of slow. To see what's going on here, I made the following script `make_many_fibers.rb: ```ruby # make_many_fibers.rb GC.disable MAX = 2**20 FIBERS = [] MAX.times do fiber = Fiber.new do loop do Fiber.yield end end fiber.resume FIBERS << fiber end ``` And then ran it under perf to generate a combined userspace/kernelspace flamegrah: ``` sudo swapoff --all # make sure we don't get page faults from swap echo madvise | sudo tee /sys/kernel/mm/transparent_hugepage/enable # make sure THP doesn't cause faults echo -1 | sudo tee /proc/sys/kernel/perf_event_paranoid # allow unprivileged users to run perf echo 1000000000 | sudo tee /proc/sys/vm/max_map_count # boost mapping count % ruby --version ruby 3.3.0dev (2023-09-05T08:35:28Z master 5b146eb5a1) [x86_64-linux] perf record -F 999 -g -- ruby make_many_fibers.rb perf script report flamegraph ``` ![](flamegraph_make_many_fibers.png) (Also you can look at the [interactive HTML version](https://gistpreview.github.io/?1eef2ef1e521742c9f7778a14483d939)) You can see almost all of the time spent in the process of making fibers is in the kernel. A few things jump out at me. ### Fiber memory mappings Firstly, let's discuss the process of how memory is mapped for the fibers, in `fiber_pool_expand`. The code for this makes a single call to `mmap(2)` to produce a mapping large enough to hold a pool of fibers (up to 1024) - this happens in [fiber_pool_allocate_memory]https://github.com/ruby/ruby/blob/c87f2a4f156477…) Then, we divide up that space for each fiber in [fiber_pool_expand](https://github.com/ruby/ruby/blob/c87f2a4f156477ba962de1…. Each fiber gets an area for its Ruby stack, for its C stack, and a "guard page" below the stack so that a fiber which tries to grow its native stack out of bounds generates a page fault instead of trashing some random memory. That guard page is marked non-readable and non-writable through a call to `mprotect(2)` [here](https://github.com/ruby/ruby/blob/c87f2a4f156477ba962de19866a1f6298d5…. Despite this starting out as one mapping, on Linux a single memory mapping must actually have the same permissions for _all pages_ in the mapping. Thus, when a page inside a mapping has its protection flags changed, the mapping must actualy be split up into three; an area before the page being changed, a mapping containing just the page being changed, and the area afterwards. We can see in the flamegraph that a huge amount of kernel time is spent in the call to `mprotect`, doing `__split_vma`. Since we know ahead of time what the layout of the fiber pool's mappings is going to be, it might be worth experimenting with explicitly making two `mmap` calls per fiber; one to set up the memory needed, and one with the guard page. This would avoid the continous splitting as we `mprotect` the guard pages inside the one mapping. Another thing we could try here is using mmap's `MAP_GROWSDOWN` option instead of explicitly making guard pages ourselves. The [docs](https://man7.org/linux/man-pages/man2/mmap.2.html) say that "this flag is used for stacks" and automatically allocates a guard page which will attempt to grow the mapping if hit. I haven't looked too hard at how it's implemented, but it might mean we can use a _single_ mapping per fiber, with the guard page managed by the kernel. ### Page faults The second place we see a ton of kernel time being spent is in the page fault handler. This happens because when the mapping is created with `mmap`, the kernel doesn't actually back it with any memory; instead, it lazily waits for the application to try and access the memory range and only makes real memory available to the application then. We hit the page fault handler in two main places; `coroutine_initialize` (this is where the fiber's C stack is used for the first time), and `vm_push_frame` (this is where the fibers Ruby stack is used for the first time). This is why, in the profile @ioquatix shared before, we see more time in `vm_push_frame`. Each fibers first call to this method takes longer because it needs to allocate the initial page of Ruby stack. The original script in this issue makes more of the calls to `vm_push_frame` the initial call for a fiber because it has more fibers & the same number of iterations. There isn't a whole lot which can be done about this overhead unfortunately. The only thing which would really make a difference here is using `MAP_LOCKED` to eagerly allocate all the real memory when the mapping is first made, but that would be extrodinarily wasteful of real system memory. ## Transfering between existing fibers Once the fibers are all created (and used for the first time, to fault in the stack), the assertion in the original issue is that it should be a constant-time operation to transfer between fibers, irrespective of tthe number of fibers in the application. However, the script in @ioquatix's last comment shows the rate of fiber-transfer operations dropping off as more fibers participate in the benchmark. To debug this issue, I modified @ioquatix's script slightly to measure some performance counters with `perf` for each of the test iterations: ```ruby # transfer_many_fibers.rb require 'open3' require 'json' require 'csv' # This program shows how the performance of Fiber.transfer degrades as the fiber # count increases MAX = 2**20 FIBERS = [] MAX.times do fiber = Fiber.new do loop do Fiber.yield end end fiber.resume FIBERS << fiber end REPEATS = 10_000_000 PERF_COUNTERS = [ 'page-faults', 'major-faults', 'minor-faults', 'cpu-cycles:u', 'cpu-cycles:k', 'cache-misses', 'cache-references', 'L1-dcache-load-misses', 'L1-dcache-loads' ,'LLC-load-misses', 'LLC-loads', 'dTLB-loads', 'dTLB-load-misses', 'dTLB-stores', 'dTLB-store-misses' ] def with_perf_counters perf_cmd = [ 'perf', 'stat', '-e', PERF_COUNTERS.join(','), '-j', '-p', Process.pid.to_s, '-o', '/proc/self/fd/1' ] Open3.popen2(*perf_cmd) do |stdin, stdout, wait_thr| block_result = yield Process.kill :SIGINT, wait_thr.pid counters = {} stdout.each_line do |ln| parsed_ln = JSON.parse ln counters[parsed_ln['event']] = parsed_ln['counter-value'].to_i end wait_thr.value return [block_result, counters] end end def run(fibers, repeats = REPEATS) count = 0 t0 = Process.clock_gettime(Process::CLOCK_MONOTONIC) while count < repeats fibers.each do |fiber| count += 1 break if count >= repeats fiber.resume end end elapsed = Process.clock_gettime(Process::CLOCK_MONOTONIC) - t0 end # Print results as a CSV table: puts CSV.generate_line [ 'fibers', 'elapsed time (s)', 'rate (t/s)', *PERF_COUNTERS ] GC.disable 21.times do |i| GC.start limit = 2**i fibers = FIBERS[0...limit] elapsed, perf_counters = with_perf_counters { run(fibers) } rate = REPEATS / elapsed puts CSV.generate_line [ limit, elapsed, rate, *PERF_COUNTERS.map { perf_counters[_1] }, ] end ``` This generats a table like the previous comment, but also includes performance counter information from `perf`. I ran this as follows: ``` sudo swapoff --all # make sure we don't get page faults from swap echo madvise | sudo tee /sys/kernel/mm/transparent_hugepage/enable # make sure THP doesn't cause faults echo -1 | sudo tee /proc/sys/kernel/perf_event_paranoid # allow unprivileged users to run perf echo 1000000000 | sudo tee /proc/sys/vm/max_map_count # boost mapping count % ruby --version ruby 3.3.0dev (2023-09-05T08:35:28Z master 5b146eb5a1) [x86_64-linux] ruby transfer_many_fibers.rb ``` and obtained the following CSV data as a result: ``` fibers,elapsed time (s),rate (t/s),page-faults,major-faults,minor-faults,cpu-cycles:u,cpu-cycles:k,cache-misses,cache-references,L1-dcache-load-misses,L1-dcache-loads,LLC-load-misses,LLC-loads,dTLB-loads,dTLB-load-misses,dTLB-stores,dTLB-store-misses 1,1.4039703360003841,7122657.611476247,3,0,3,5859475245,12694559,3387,54987,165432,7146119413,650,16262,7145394321,4252,4601866193,7320 2,1.2886379399997168,7760131.600659063,1,0,1,5439823427,11350600,5964,55424,189086,6621658447,500,15200,6622892928,5438,4258132955,6574 4,1.258153214000231,7948157.576298307,0,0,0,5310310212,13089610,10449,68069,294892,6335968536,290,16860,6345118100,25997,4058742655,6802 8,1.253403425000215,7978277.225465762,0,0,0,5279962922,34494806,5446,51855,62076301,6192431913,900,16039,6179777983,44444,3939369328,6815 16,1.2689530819998254,7880512.007772858,0,0,0,5370474254,10763313,3844,47457,183940406,6102241668,765,16165,6103205916,26204,3910352255,6246 32,1.2346172180004942,8099676.445623648,0,0,0,5332621133,15694092,10154,64114,200680305,6063273925,462,15166,6068903340,38317,3883690997,11413 64,1.2704579209994336,7871177.655481325,0,0,0,5346794521,12588604,9447,56960,232002452,6059702410,638,15011,6058457551,17290,3878188080,8864 128,1.26315632800015,7916676.485983461,0,0,0,5343576341,12619817,30122,172656,254975275,6032357554,781,28931,6043258633,16401,3866060907,7708 256,1.3926949320002677,7180323.393320194,1,0,1,5946049052,16997016,232957,228631165,263358837,6037282294,1965,49843868,6038606356,14063,3867631144,7523 512,1.4688533830003507,6808031.431682799,0,0,0,6499307194,16462834,1098041,459635153,271677968,6042696127,5034,97729427,6041134724,1340316,3870403582,913873 1024,1.6829085890003626,5942093.388411512,0,0,0,7586548807,18469725,17423890,505379678,289076442,6049202803,558254,99886434,6055483248,10667121,3875545360,8659232 2048,2.458299625000109,4067852.3880096828,0,0,0,10614911431,34628829,125912094,586214908,293999643,6065587295,9686614,109485434,6074510477,12782326,3886950850,9275023 4096,3.8801752910003415,2577203.154505403,0,0,0,14523389421,54902097,332459456,565424689,294461987,6081202395,72540001,112161028,6082385994,18416444,3895766223,3191327 8192,4.739300166999783,2110016.172773987,0,0,0,16748731849,80070197,433472922,584586094,293148050,6082602630,93201829,114523043,6098901364,17956895,3898469812,4034203 16384,5.312199805000091,1882459.313858551,0,0,0,18067407945,89930922,494108236,594290763,292332035,6085798157,104621395,114785396,6094092659,17858483,3896705126,4349967 32768,5.714678685999388,1749879.6606884277,0,0,0,18954140751,57310406,520112168,600784408,292360264,6087857552,110260489,114733525,6089971523,17990727,3897881974,4273404 65536,5.85913169899959,1706737.5361621308,0,0,0,19225994828,58272894,527013755,601246452,292342290,6087916819,111582260,114827548,6091113925,18252983,3898391171,4059701 131072,5.90900381099982,1692332.6367440557,0,0,0,19223289411,60175735,530254916,600266994,292030029,6085240814,111810664,114751374,6084010298,18191953,3891766484,4108941 262144,5.8664713339994705,1704602.2098573,0,0,0,19168022353,66616904,531536818,601173015,291660876,6086962661,111537615,114434876,6090071817,17934617,3900912972,4454238 524288,5.871122640999602,1703251.7648613497,0,0,0,19239854173,74336965,531516412,601003077,291588311,6087162576,111521049,114462843,6092648529,17901966,3902304196,4484503 1048576,5.919364534000124,1689370.5299886826,0,0,0,19290077173,162339116,532576986,603934645,291400193,6088300500,111567224,114528793,6087885216,17794051,3898248975,4611646 ``` ### Page faults Firstly, the number of page faults in the transfer process is zero. This is expected; each of these fibers was already resumed once at the top of the script, so their stacks are faulted in. Thus, transferring between them incurs no page fault. (sidebar: My initial version of this test actually _did_ generate a large number of page faults. Eventually, I worked out it was because I was running the script as root. Ruby's `Process.spawn` uses `vfork(2)` to create the new process to be executed normally, BUT it uses `fork(2)` when the process is privileged. When you use real fork to make a new process, Linux marks all of your memory pages as read-only, so they can be shared with the just-forked process with copy-on-write semantics - even though the child process calls `exec(2)` straight afterwards! The next time your process tries to write to a page, it takes a page fault. The fault handler works out that the page is no longer shared (since the child process exec'd) and marks it as writable again. Anyway I spent _hours_ trying to find out where these faults were coming from... glad I did though!) ### Cache misses Based on this data, my assessment is that the scenarios with more fibers involved in the transfer dance are slower because they put more pressure on the CPU's various caches. It's quite confusing what all the various cache measurements mean, but I think the `cache-misses` metric measures all memory accesses which missed _all_ the caches, based on [this Stackoverflow answer](https://stackoverflow.com/questions/55035313/how-does-linux-perf-ca…. It seems that the overall time spent on the benchmark is _very_ strongly correlated to the total `cache-misses`: ![](cache_misses_vs_time.png) Based on this, I believe transfering between multiple fibers in this benchmark gets slower because each fiber has its stack in a different part of the system's memory, and so with many fibers you're far less likely to get a CPU cache hit when loading that fibers stack. I don't think there's _really_ anything which can be done here; working on large amounts of data or instructions which don't fit into CPU cache is _always_ much slower than smaller bits which do. This benchmark is particuarly pathalogical because all it does is flip between fibers; in a real application hopfully the CPU caches would quickly be filled up with some relevant data for the fiber that's running. ## Conclusion I think it's worth experimenting with manually making a single `MAP_GROWSDOWN` mapping per fiber to see if that can improve fiber creation time by avoiding having the kernel split the mappings sequentially. However, I don't think there's a real problem with fiber transfers once the fibers have been created. ---------------------------------------- Bug #17263: Fiber context switch degrades with number of fibers, limit on number of fibers https://bugs.ruby-lang.org/issues/17263#change-104638 * Author: ciconia (Sharon Rosner) * Status: Closed * Priority: Normal * ruby -v: 2.7.1 * Backport: 2.5: UNKNOWN, 2.6: UNKNOWN, 2.7: UNKNOWN ---------------------------------------- I'm working on developing [Polyphony](https://github.com/digital-fabric/polyphony), a Ruby gem for writing highly-concurrent Ruby programs with fibers. In the course of my work I have come up against two problems using Ruby fibers: 1. Fiber context switching performance seem to degrade as the number of fibers is increased. This is both with `Fiber#transfer` and `Fiber#resume/Fiber.yield`. 2. The number of concurrent fibers that can exist at any time seems to be limited. Once a certain number is reached (on my system this seems to be 31744 fibers), calling `Fiber#transfer` will raise a `FiberError` with the message `can't set a guard page: Cannot allocate memory`. This is not due to RAM being saturated. With 10000 fibers, my test program hovers at around 150MB RSS (on Ruby 2.7.1). Here's a program for testing the performance of `Fiber#transfer`: ```ruby # frozen_string_literal: true require 'fiber' class Fiber attr_accessor :next end def run(num_fibers) count = 0 GC.start GC.disable first = nil last = nil supervisor = Fiber.current num_fibers.times do fiber = Fiber.new do loop do count += 1 if count == 1_000_000 supervisor.transfer else Fiber.current.next.transfer end end end first ||= fiber last.next = fiber if last last = fiber end last.next = first t0 = Time.now first.transfer elapsed = Time.now - t0 rss = `ps -o rss= -p #{Process.pid}`.to_i puts "fibers: #{num_fibers} rss: #{rss} count: #{count} rate: #{count / elapsed}" rescue Exception => e puts "Stopped at #{count} fibers" p e end run(100) run(1000) run(10000) run(100000) ``` With Ruby 2.6.5 I'm getting: ``` fibers: 100 rss: 23212 count: 1000000 rate: 3357675.1688139187 fibers: 1000 rss: 31292 count: 1000000 rate: 2455537.056439736 fibers: 10000 rss: 127388 count: 1000000 rate: 954251.1674325482 Stopped at 22718 fibers #<FiberError: can't set a guard page: Cannot allocate memory> ``` With Ruby 2.7.1 I'm getting: ``` fibers: 100 rss: 23324 count: 1000000 rate: 3443916.967616508 fibers: 1000 rss: 34676 count: 1000000 rate: 2333315.3862491543 fibers: 10000 rss: 151364 count: 1000000 rate: 916772.1008060966 Stopped at 31744 fibers #<FiberError: can't set a guard page: Cannot allocate memory> ``` With ruby-head I get an almost identical result to that of 2.7.1. As you can see, the performance degradation is similar in all the three versions of Ruby, going from ~3.4M context switches per second for 100 fibers to less then 1M context switches per second for 10000 fibers. Running with 100000 fibers fails to complete. Here's a program for testing the performance of `Fiber#resume/Fiber.yield`: ```ruby # frozen_string_literal: true require 'fiber' class Fiber attr_accessor :next end # This program shows how the performance of Fiber.transfer degrades as the fiber # count increases def run(num_fibers) count = 0 GC.start GC.disable fibers = [] num_fibers.times do fibers << Fiber.new { loop { Fiber.yield } } end t0 = Time.now while count < 1000000 fibers.each do |f| count += 1 f.resume end end elapsed = Time.now - t0 puts "fibers: #{num_fibers} count: #{count} rate: #{count / elapsed}" rescue Exception => e puts "Stopped at #{count} fibers" p e end run(100) run(1000) run(10000) run(100000) ``` With Ruby 2.7.1 I'm getting the following output: ``` fibers: 100 count: 1000000 rate: 3048230.049946255 fibers: 1000 count: 1000000 rate: 2362235.6455160403 fibers: 10000 count: 1000000 rate: 950251.7621725246 Stopped at 21745 fibers #<FiberError: can't set a guard page: Cannot allocate memory> ``` As I understand it, theoretically at least switching between fibers should have a constant cost in terms of CPU cycles, irrespective of the number of fibers currently existing in memory. I am completely ignorant the implementation details of Ruby fibers, so at least for now I don't have any idea where this problem is coming from. ---Files-------------------------------- clipboard-202308251514-grqb1.png (81.3 KB) clipboard-202308251514-r7g4l.png (81 KB) clipboard-202308251538-kmofk.png (13.8 KB) flamegraph_make_many_fibers.png (471 KB) cache_misses_vs_time.png (42.5 KB) -- https://bugs.ruby-lang.org/

1 0

[ruby-core:114780] [Ruby master Bug#18257] rb_mRubyVMFrozenCore is broken by GC run
by vo.x (Vit Ondruch) 15 Sep '23

15 Sep '23

Issue #18257 has been updated by vo.x (Vit Ondruch). Trying to reproduce all the steps, I still observe the behavior as described in comment #18257-12. I'll keep around the patch as described in #18257-14 until this is fixed properly. ---------------------------------------- Bug #18257: rb_mRubyVMFrozenCore is broken by GC run https://bugs.ruby-lang.org/issues/18257#change-104622 * Author: vo.x (Vit Ondruch) * Status: Feedback * Priority: Normal * ruby -v: ruby 3.0.3p157 (2021-11-24 revision 3fb7d2cadc) [x86_64-linux] * Backport: 2.6: UNKNOWN, 2.7: UNKNOWN, 3.0: UNKNOWN ---------------------------------------- Testing Ruby with SystemTap on RHEL9 beta following these steps: ~~~ $ stap -v /usr/share/doc/ruby-doc/ruby-exercise.stp & $ ruby -e '[1, 2, 3].push(4)' ~~~ I get the following error: ~~~ /usr/share/rubygems/rubygems/errors.rb:181: [BUG] Segmentation fault at 0x0000000000000014 ruby 3.0.2p107 (2021-07-07 revision 0db68f0233) [powerpc64le-linux] -- Control frame information ----------------------------------------------- c:0008 p:0028 s:0032 e:000027 CLASS /usr/share/rubygems/rubygems/errors.rb:181 c:0007 p:0110 s:0025 e:000024 CLASS /usr/share/rubygems/rubygems/errors.rb:153 c:0006 p:0007 s:0022 e:000021 TOP /usr/share/rubygems/rubygems/errors.rb:9 [FINISH] c:0005 p:---- s:0019 e:000018 CFUNC :require c:0004 p:0037 s:0014 e:000013 TOP /usr/share/rubygems/rubygems.rb:19 [FINISH] c:0003 p:---- s:0011 e:000010 CFUNC :require c:0002 p:0012 s:0006 e:000005 TOP <internal:gem_prelude>:2 [FINISH] c:0001 p:0000 s:0003 E:0026c0 (none) [FINISH] -- Ruby level backtrace information ---------------------------------------- <internal:gem_prelude>:2:in `<internal:gem_prelude>' <internal:gem_prelude>:2:in `require' /usr/share/rubygems/rubygems.rb:19:in `<top (required)>' /usr/share/rubygems/rubygems.rb:19:in `require' /usr/share/rubygems/rubygems/errors.rb:9:in `<top (required)>' /usr/share/rubygems/rubygems/errors.rb:153:in `<module:Gem>' /usr/share/rubygems/rubygems/errors.rb:181:in `<class:SourceFetchProblem>' -- C level backtrace information ------------------------------------------- /lib64/libruby.so.3.0(0x7fffb3b06ba0) [0x7fffb3b06ba0] /lib64/libruby.so.3.0(0x7fffb38d9680) [0x7fffb38d9680] /lib64/libruby.so.3.0(0x7fffb3a4b9d8) [0x7fffb3a4b9d8] linux-vdso64.so.1(__kernel_sigtramp_rt64+0x0) [0x7fffb3ca0464] [0x7fffb3a67ff8] /lib64/libruby.so.3.0(rb_str_dup+0x130) [0x7fffb3a6b950] /lib64/libruby.so.3.0(rb_class_path+0x3c) [0x7fffb3ac72ac] /lib64/libruby.so.3.0(rb_dtrace_setup+0x134) [0x7fffb3ae46a4] [0x7fffb3ae4a00] [0x7fffb3ae7644] [0x7fffb3aeba5c] /lib64/libruby.so.3.0(rb_vm_exec+0x140) [0x7fffb3af1710] /lib64/libruby.so.3.0(rb_iseq_eval+0x164) [0x7fffb3af29f4] [0x7fffb394ce68] /lib64/libruby.so.3.0(rb_require_string+0x44) [0x7fffb394e7f4] /lib64/libruby.so.3.0(rb_f_require+0x1c) [0x7fffb394e88c] [0x7fffb3acf538] [0x7fffb3ae4900] [0x7fffb3ae7644] [0x7fffb3aeba5c] /lib64/libruby.so.3.0(rb_vm_exec+0x140) [0x7fffb3af1710] /lib64/libruby.so.3.0(rb_iseq_eval+0x164) [0x7fffb3af29f4] [0x7fffb394ce68] /lib64/libruby.so.3.0(rb_require_string+0x44) [0x7fffb394e7f4] /lib64/libruby.so.3.0(rb_f_require+0x1c) [0x7fffb394e88c] [0x7fffb3acf538] [0x7fffb3ae4900] [0x7fffb3ae7644] [0x7fffb3aeba5c] /lib64/libruby.so.3.0(rb_vm_exec+0x140) [0x7fffb3af1710] /lib64/libruby.so.3.0(rb_iseq_eval+0x164) [0x7fffb3af29f4] [0x7fffb3b15f60] [0x7fffb3a4826c] [0x7fffb3a499d8] /lib64/libruby.so.3.0(ruby_process_options+0x158) [0x7fffb3a4a778] /lib64/libruby.so.3.0(ruby_options+0xf4) [0x7fffb38e5904] [0x11a360a60] [0x7fffb35d7ca4] [0x7fffb35d7e80] -- Other runtime information ----------------------------------------------- * Loaded script: ruby * Loaded features: 0 enumerator.so 1 thread.rb 2 rational.so 3 complex.so 4 ruby2_keywords.rb 5 /usr/lib64/ruby/enc/encdb.so 6 /usr/lib64/ruby/enc/trans/transdb.so 7 /usr/lib64/ruby/rbconfig.rb 8 /usr/share/rubygems/rubygems/compatibility.rb 9 /usr/share/rubygems/rubygems/defaults.rb 10 /usr/share/rubygems/rubygems/deprecate.rb * Process memory map: 11a360000-11a370000 r-xp 00000000 fd:00 34097694 /usr/bin/ruby 11a370000-11a380000 r--p 00000000 fd:00 34097694 /usr/bin/ruby 11a380000-11a390000 rw-p 00010000 fd:00 34097694 /usr/bin/ruby 1000d490000-1000d6b0000 rw-p 00000000 00:00 0 [heap] 7fffaf470000-7fffaf8d0000 r--s 00000000 fd:00 67811909 /usr/lib64/libruby.so.3.0.2 7fffaf8d0000-7fffaf8f0000 r--s 00000000 fd:00 34097694 /usr/bin/ruby 7fffaf8f0000-7fffaf900000 r-xp 00000000 fd:00 100999014 /usr/lib64/ruby/enc/trans/transdb.so 7fffaf900000-7fffaf910000 r--p 00000000 fd:00 100999014 /usr/lib64/ruby/enc/trans/transdb.so 7fffaf910000-7fffaf920000 rw-p 00000000 00:00 0 7fffaf920000-7fffaf930000 r-xp 00000000 fd:00 67811915 /usr/lib64/ruby/enc/encdb.so 7fffaf930000-7fffaf940000 r--p 00000000 fd:00 67811915 /usr/lib64/ruby/enc/encdb.so 7fffaf940000-7fffaf950000 rw-p 00000000 00:00 0 7fffaf950000-7fffaf960000 ---p 00000000 00:00 0 7fffaf960000-7fffafa10000 rw-p 00000000 00:00 0 7fffafa10000-7fffafa20000 ---p 00000000 00:00 0 7fffafa20000-7fffafad0000 rw-p 00000000 00:00 0 7fffafad0000-7fffafae0000 ---p 00000000 00:00 0 7fffafae0000-7fffafb90000 rw-p 00000000 00:00 0 7fffafb90000-7fffafba0000 ---p 00000000 00:00 0 7fffafba0000-7fffafc50000 rw-p 00000000 00:00 0 7fffafc50000-7fffafc60000 ---p 00000000 00:00 0 7fffafc60000-7fffafd10000 rw-p 00000000 00:00 0 7fffafd10000-7fffafd20000 ---p 00000000 00:00 0 7fffafd20000-7fffafdd0000 rw-p 00000000 00:00 0 7fffafdd0000-7fffafde0000 ---p 00000000 00:00 0 7fffafde0000-7fffafe90000 rw-p 00000000 00:00 0 7fffafe90000-7fffafea0000 ---p 00000000 00:00 0 7fffafea0000-7fffaff50000 rw-p 00000000 00:00 0 7fffaff50000-7fffaff60000 ---p 00000000 00:00 0 7fffaff60000-7fffb0010000 rw-p 00000000 00:00 0 7fffb0010000-7fffb0020000 ---p 00000000 00:00 0 7fffb0020000-7fffb00d0000 rw-p 00000000 00:00 0 7fffb00d0000-7fffb00e0000 ---p 00000000 00:00 0 7fffb00e0000-7fffb0190000 rw-p 00000000 00:00 0 7fffb0190000-7fffb01a0000 ---p 00000000 00:00 0 7fffb01a0000-7fffb0250000 rw-p 00000000 00:00 0 7fffb0250000-7fffb0260000 ---p 00000000 00:00 0 7fffb0260000-7fffb0310000 rw-p 00000000 00:00 0 7fffb0310000-7fffb0320000 ---p 00000000 00:00 0 7fffb0320000-7fffb03d0000 rw-p 00000000 00:00 0 7fffb03d0000-7fffb03e0000 ---p 00000000 00:00 0 7fffb03e0000-7fffb0490000 rw-p 00000000 00:00 0 7fffb0490000-7fffb04a0000 ---p 00000000 00:00 0 7fffb04a0000-7fffb0550000 rw-p 00000000 00:00 0 7fffb0550000-7fffb0560000 ---p 00000000 00:00 0 7fffb0560000-7fffb0610000 rw-p 00000000 00:00 0 7fffb0610000-7fffb0620000 ---p 00000000 00:00 0 7fffb0620000-7fffb06d0000 rw-p 00000000 00:00 0 7fffb06d0000-7fffb06e0000 ---p 00000000 00:00 0 7fffb06e0000-7fffb0790000 rw-p 00000000 00:00 0 7fffb0790000-7fffb07a0000 ---p 00000000 00:00 0 7fffb07a0000-7fffb0850000 rw-p 00000000 00:00 0 7fffb0850000-7fffb0860000 ---p 00000000 00:00 0 7fffb0860000-7fffb0910000 rw-p 00000000 00:00 0 7fffb0910000-7fffb0920000 ---p 00000000 00:00 0 7fffb0920000-7fffb09d0000 rw-p 00000000 00:00 0 7fffb09d0000-7fffb09e0000 ---p 00000000 00:00 0 7fffb09e0000-7fffb0a90000 rw-p 00000000 00:00 0 7fffb0a90000-7fffb0aa0000 ---p 00000000 00:00 0 7fffb0aa0000-7fffb0b50000 rw-p 00000000 00:00 0 7fffb0b50000-7fffb0b60000 ---p 00000000 00:00 0 7fffb0b60000-7fffb0c10000 rw-p 00000000 00:00 0 7fffb0c10000-7fffb0c20000 ---p 00000000 00:00 0 7fffb0c20000-7fffb0cd0000 rw-p 00000000 00:00 0 7fffb0cd0000-7fffb0ce0000 ---p 00000000 00:00 0 7fffb0ce0000-7fffb0d90000 rw-p 00000000 00:00 0 7fffb0d90000-7fffb0da0000 ---p 00000000 00:00 0 7fffb0da0000-7fffb0e50000 rw-p 00000000 00:00 0 7fffb0e50000-7fffb0e60000 ---p 00000000 00:00 0 7fffb0e60000-7fffb0f10000 rw-p 00000000 00:00 0 7fffb0f10000-7fffb0f20000 ---p 00000000 00:00 0 7fffb0f20000-7fffb0fd0000 rw-p 00000000 00:00 0 7fffb0fd0000-7fffb0fe0000 ---p 00000000 00:00 0 7fffb0fe0000-7fffb1090000 rw-p 00000000 00:00 0 7fffb1090000-7fffb10a0000 ---p 00000000 00:00 0 7fffb10a0000-7fffb32e0000 rw-p 00000000 00:00 0 7fffb32e0000-7fffb3340000 r--p 00000000 fd:00 33555845 /usr/lib/locale/en_US.utf8/LC_CTYPE 7fffb3340000-7fffb3420000 r-xp 00000000 fd:00 67172714 /usr/lib64/libm.so.6 7fffb3420000-7fffb3430000 r--p 000d0000 fd:00 67172714 /usr/lib64/libm.so.6 7fffb3430000-7fffb3440000 rw-p 000e0000 fd:00 67172714 /usr/lib64/libm.so.6 7fffb3440000-7fffb3480000 r-xp 00000000 fd:00 67172871 /usr/lib64/libcrypt.so.2.0.0 7fffb3480000-7fffb3490000 r--p 00030000 fd:00 67172871 /usr/lib64/libcrypt.so.2.0.0 7fffb3490000-7fffb34a0000 rw-p 00000000 00:00 0 7fffb34a0000-7fffb3540000 r-xp 00000000 fd:00 67172912 /usr/lib64/libgmp.so.10.4.0 7fffb3540000-7fffb3550000 r--p 00090000 fd:00 67172912 /usr/lib64/libgmp.so.10.4.0 7fffb3550000-7fffb3560000 rw-p 000a0000 fd:00 67172912 /usr/lib64/libgmp.so.10.4.0 7fffb3560000-7fffb3580000 r-xp 00000000 fd:00 67172832 /usr/lib64/libz.so.1.2.11 7fffb3580000-7fffb3590000 r--p 00010000 fd:00 67172832 /usr/lib64/libz.so.1.2.11 7fffb3590000-7fffb35a0000 rw-p 00020000 fd:00 67172832 /usr/lib64/libz.so.1.2.11 7fffb35a0000-7fffb37e0000 r-xp 00000000 fd:00 67172711 /usr/lib64/libc.so.6 7fffb37e0000-7fffb37f0000 r--p 00230000 fd:00 67172711 /usr/lib64/libc.so.6 7fffb37f0000-7fffb3800000 rw-p 00240000 fd:00 67172711 /usr/lib64/libc.so.6 7fffb3800000-7fffb3c30000 r-xp 00000000 fd:00 67811909 /usr/lib64/libruby.so.3.0.2 7fffb3c30000-7fffb3c40000 ---p 00430000 fd:00 67811909 /usr/lib64/libruby.so.3.0.2 7fffb3c40000-7fffb3c50000 r--p 00430000 fd:00 67811909 /usr/lib64/libruby.so.3.0.2 7fffb3c50000-7fffb3c60000 rw-p 00440000 fd:00 67811909 /usr/lib64/libruby.so.3.0.2 7fffb3c60000-7fffb3c70000 rw-p 00000000 00:00 0 7fffb3c70000-7fffb3c80000 r--s 00000000 fd:00 100673889 /usr/lib64/gconv/gconv-modules.cache 7fffb3c80000-7fffb3ca0000 r--p 00000000 00:00 0 [vvar] 7fffb3ca0000-7fffb3cb0000 r-xp 00000000 00:00 0 [vdso] 7fffb3cb0000-7fffb3d00000 r-xp 00000000 fd:00 67172707 /usr/lib64/ld64.so.2 7fffb3d00000-7fffb3d10000 r--p 00040000 fd:00 67172707 /usr/lib64/ld64.so.2 7fffb3d10000-7fffb3d20000 rw-p 00050000 fd:00 67172707 /usr/lib64/ld64.so.2 7fffdee00000-7fffdf600000 rw-p 00000000 00:00 0 [stack] ~~~ This should be the full BT: ~~~ (gdb) bt #0 0x00007fffa5711550 in uleb128 (p=0x10039917f10) at addr2line.c:200 #1 di_read_die (reader=reader@entry=0x10039917eb8, die=die@entry=0x10039917dc8) at addr2line.c:1343 #2 0x00007fffa5714574 in debug_info_read (offset=<optimized out>, lines=<optimized out>, traces=<optimized out>, num_traces=<optimized out>, reader=<optimized out>) at addr2line.c:1630 #3 fill_lines (num_traces=num_traces@entry=39, traces=traces@entry=0x7fffa585d778 <trace>, check_debuglink=check_debuglink@entry=0, objp=objp@entry=0x10039919370, lines=lines@entry=0x100399756f0, offset=<optimized out>, offset@entry=0) at addr2line.c:1887 #4 0x00007fffa5714f28 in follow_debuglink (offset=0, lines=0x100399756f0, objp=0x10039919370, traces=<optimized out>, num_traces=39, debuglink=0x7fffa14e01e4 "ruby-3.0.2-155.el9.ppc64le.debug") at addr2line.c:574 #5 fill_lines (num_traces=num_traces@entry=39, traces=traces@entry=0x7fffa585d778 <trace>, check_debuglink=check_debuglink@entry=1, objp=0x10039919370, objp@entry=0x100399193f0, lines=lines@entry=0x100399756f0, offset=<optimized out>, offset@entry=-1) at addr2line.c:1925 #6 0x00007fffa571576c in rb_dump_backtrace_with_lines (num_traces=<optimized out>, traces=0x7fffa585d778 <trace>) at addr2line.c:2286 #7 0x00007fffa5706bac in rb_print_backtrace () at vm_dump.c:760 #8 rb_vm_bugreport (ctx=<optimized out>) at vm_dump.c:998 #9 0x00007fffa54d9680 in rb_bug_for_fatal_signal (default_sighandler=0x0, sig=<optimized out>, ctx=0x100399197c0, fmt=0x7fffa574e8f0 "Segmentation fault at %p") at error.c:786 #10 0x00007fffa564b9d8 in sigsegv (sig=<optimized out>, info=0x1003991a540, ctx=0x100399197c0) at signal.c:960 #11 <signal handler called> #12 0x00007fffa5667ff8 in str_new_frozen_buffer (klass=klass@entry=1100477014720, orig=orig@entry=1100476844400, copy_encoding=copy_encoding@entry=1) at string.c:1329 #13 0x00007fffa566b950 in str_new_frozen (orig=1100476844400, klass=1100477014720) at string.c:1297 #14 str_duplicate_setup (dup=1100478149120, str=1100476844400, klass=1100477014720) at string.c:1570 #15 str_duplicate (str=1100476844400, klass=1100477014720) at string.c:1602 #16 rb_str_dup (str=1100476844400) at string.c:1608 #17 0x00007fffa56c72ac in rb_class_path (klass=1100476844480) at variable.c:173 #18 0x00007fffa56e46a4 in rb_dtrace_setup (ec=<optimized out>, klass=1100476844480, id=159, args=0x7fffe9d953d8) at vm.c:449 #19 0x00007fffa56e4a00 in vm_call_cfunc_with_frame (ec=<optimized out>, reg_cfp=0x7fffa4ecfe50, calling=<optimized out>) at vm_insnhelper.c:2916 #20 0x00007fffa56e7644 in vm_sendish (ec=0x10039811cf0, reg_cfp=0x7fffa4ecfe50, cd=0x100399a8db0, block_handler=<optimized out>, method_explorer=<optimized out>) at vm_callinfo.h:336 #21 0x00007fffa56eba5c in vm_exec_core (ec=0x10039811cf0, initial=<optimized out>, initial@entry=0) at insns.def:789 #22 0x00007fffa56f1710 in rb_vm_exec (ec=0x10039811cf0, mjit_enable_p=<optimized out>) at vm.c:2172 #23 0x00007fffa56f29f4 in rb_iseq_eval (iseq=0x100398aa7c0) at vm.c:2409 #24 0x00007fffa554ce68 in load_iseq_eval (fname=1100477137480, ec=0x10039811cf0) at load.c:594 #25 require_internal (ec=ec@entry=0x10039811cf0, fname=<optimized out>, fname@entry=1100476430040, exception=exception@entry=1) at load.c:1065 #26 0x00007fffa554e7f4 in rb_require_string (fname=1100476430040) at load.c:1142 #27 0x00007fffa554e88c in rb_f_require (obj=<optimized out>, fname=<optimized out>) at load.c:838 #28 0x00007fffa56cf538 in ractor_safe_call_cfunc_1 (recv=<optimized out>, argc=<optimized out>, argv=<optimized out>, func=<optimized out>) at vm_insnhelper.c:2750 #29 0x00007fffa56e4900 in vm_call_cfunc_with_frame (ec=0x10039811cf0, reg_cfp=0x7fffa4ecff30, calling=<optimized out>) at vm_insnhelper.c:2926 #30 0x00007fffa56e7644 in vm_sendish (ec=0x10039811cf0, reg_cfp=0x7fffa4ecff30, cd=0x10039901e50, block_handler=<optimized out>, method_explorer=<optimized out>) at vm_callinfo.h:336 #31 0x00007fffa56eba5c in vm_exec_core (ec=0x10039811cf0, initial=<optimized out>, initial@entry=0) at insns.def:789 #32 0x00007fffa56f1710 in rb_vm_exec (ec=0x10039811cf0, mjit_enable_p=<optimized out>) at vm.c:2172 #33 0x00007fffa56f29f4 in rb_iseq_eval (iseq=0x1003981b9a8) at vm.c:2409 #34 0x00007fffa554ce68 in load_iseq_eval (fname=1100476613760, ec=0x10039811cf0) at load.c:594 #35 require_internal (ec=ec@entry=0x10039811cf0, fname=<optimized out>, fname@entry=1100476614040, exception=exception@entry=1) at load.c:1065 #36 0x00007fffa554e7f4 in rb_require_string (fname=1100476614040) at load.c:1142 #37 0x00007fffa554e88c in rb_f_require (obj=<optimized out>, fname=<optimized out>) at load.c:838 #38 0x00007fffa56cf538 in ractor_safe_call_cfunc_1 (recv=<optimized out>, argc=<optimized out>, argv=<optimized out>, func=<optimized out>) at vm_insnhelper.c:2750 #39 0x00007fffa56e4900 in vm_call_cfunc_with_frame (ec=0x10039811cf0, reg_cfp=0x7fffa4ecffa0, calling=<optimized out>) at vm_insnhelper.c:2926 #40 0x00007fffa56e7644 in vm_sendish (ec=0x10039811cf0, reg_cfp=0x7fffa4ecffa0, cd=0x10039970580, block_handler=<optimized out>, method_explorer=<optimized out>) at vm_callinfo.h:336 #41 0x00007fffa56eba5c in vm_exec_core (ec=0x10039811cf0, initial=<optimized out>, initial@entry=0) at insns.def:789 #42 0x00007fffa56f1710 in rb_vm_exec (ec=0x10039811cf0, mjit_enable_p=<optimized out>) at vm.c:2172 #43 0x00007fffa56f29f4 in rb_iseq_eval (iseq=0x100398489f8) at vm.c:2409 #44 0x00007fffa5715f60 in rb_load_with_builtin_functions (feature_name=0x7fffa57b61c0 "gem_prelude", table=0x0) at builtin.c:54 #45 0x00007fffa564826c in ruby_init_prelude () at ruby.c:1498 #46 ruby_opt_init (opt=0x7fffe9d98690) at ruby.c:1521 #47 ruby_opt_init (opt=0x7fffe9d98690) at ruby.c:1506 #48 0x00007fffa56499d8 in process_options (argc=0, argc@entry=3, argv=0x7fffe9d98f10, argv@entry=0x7fffe9d98ef8, opt=opt@entry=0x7fffe9d98690) at ruby.c:1951 #49 0x00007fffa564a778 in ruby_process_options (argc=<optimized out>, argv=0x7fffe9d98ef8) at ruby.c:230 #50 0x00007fffa54e5904 in ruby_options (argc=<optimized out>, argv=0x7fffe9d98ef8) at eval.c:138 #51 0x000000010b860a60 in main (argc=<optimized out>, argv=<optimized out>) at ./main.c:50 ~~~ -- https://bugs.ruby-lang.org/

1 0

[ruby-core:114761] [Ruby master Bug#19882] :$0x should be rejected
by mame (Yusuke Endoh) 15 Sep '23

15 Sep '23

Issue #19882 has been reported by mame (Yusuke Endoh). ---------------------------------------- Bug #19882: :$0x should be rejected https://bugs.ruby-lang.org/issues/19882 * Author: mame (Yusuke Endoh) * Status: Open * Priority: Normal * Backport: 3.0: UNKNOWN, 3.1: UNKNOWN, 3.2: UNKNOWN ---------------------------------------- ``` irb(main):001> :$0x => :"$0x" ``` Since `$0x` is not a valid global variable name, I think it should be rejected unless quotation marks are used. -- https://bugs.ruby-lang.org/

3 4

[ruby-core:114766] [Ruby master Bug#9115] Logger traps all exceptions; breaks Timeout
by shyouhei (Shyouhei Urabe) 15 Sep '23

15 Sep '23

Issue #9115 has been updated by shyouhei (Shyouhei Urabe). Eregon (Benoit Daloze) wrote in #note-12: > mame (Yusuke Endoh) wrote in #note-11: > > As a better-than-nothing mitigation, it is proposed to enclose the entire `Logger::LogDevice#write` in `Thread.handle_interrupt(:never) { ... }`. > > It could be a problem if the method takes a very long time because `Timeout.timeout` cannot interrupt the execution, but such a case will be rare (hopefully). > > This sounds problematic, especially since that is doing IO, possibly even network IO (e.g. NFS, or logging over some API). Right. It's never an ultimate fix. However considering the way a log destination is designed generally, I think it's rare for that blocking IO to block indefinitely. Sure, with `handle_interrupt` a timeout can delay for seconds. That's better than never, and "never" is the way it is now. > I believe all libraries should only catch specific errors they want to rescue and if that's hard to determine than StandardError at most, never Exception. > Rescuing Exception without re-raise is always a bug (e.g. NoMemoryError/SystemStackError can be silent and that can cause pretty serious inconsistencies and indirectly what looks like memory corruption). The Logger author seems hesitating to interface with its callers at any cost (understandable). It is unfortunate that we currently have no idiomatic ways to achieve their goals. ---------------------------------------- Bug #9115: Logger traps all exceptions; breaks Timeout https://bugs.ruby-lang.org/issues/9115#change-104603 * Author: cphoenix (Chris Phoenix) * Status: Assigned * Priority: Normal * Assignee: sonots (Naotoshi Seo) * ruby -v: ruby 2.0.0p247 (2013-06-27) [i386-mingw32] ---------------------------------------- Line 577-579 of logger.rb rescue Exception => ignored warn("log writing failed. #{ignored}") end Thus, when the system times out in the middle of writing a log message, it warns "log writing failed. execution expired" and just keeps right on running. This is true in 1.9.3 as well. I haven't looked at older versions. Pardon me while I go grep "rescue Exception" in the entire Ruby codebase, and see whether I can reliably use Timeout at all... OK, you might check out C:\Ruby200\lib\ruby\gems\2.0.0\gems\activerecord-3.2.13\lib\active_record\railties\databases.rake All the other "rescue Exception" seem to re-raise it, except maybe C:\Ruby200\lib\ruby\2.0.0\xmlrpc\server.rb and C:\Ruby200\lib\ruby\gems\2.0.0\gems\activesupport-3.2.13\lib\active_support\callbacks.rb -- https://bugs.ruby-lang.org/

1 0

[ruby-core:114759] [Ruby master Bug#19881] Unary operators on calls without parentheses
by kddnewton (Kevin Newton) 14 Sep '23

14 Sep '23

Issue #19881 has been reported by kddnewton (Kevin Newton). ---------------------------------------- Bug #19881: Unary operators on calls without parentheses https://bugs.ruby-lang.org/issues/19881 * Author: kddnewton (Kevin Newton) * Status: Open * Priority: Normal * Backport: 3.0: UNKNOWN, 3.1: UNKNOWN, 3.2: UNKNOWN ---------------------------------------- At the moment it appears that you can't use unary operators when you have a call without parentheses. For example: ``` ruby - foo 1, 2, 3 ``` This seems useful, particularly for methods that perform calculations. I'm also asking because I thought this *was* allowed, so YARP allows it. If it's not, I need to explicitly add a syntax error for it. -- https://bugs.ruby-lang.org/

2 1

[ruby-core:113819] [Ruby master Feature#19720] Warning for non-linear Regexps
by Eregon (Benoit Daloze) 14 Sep '23

14 Sep '23

Issue #19720 has been reported by Eregon (Benoit Daloze). ---------------------------------------- Feature #19720: Warning for non-linear Regexps https://bugs.ruby-lang.org/issues/19720 * Author: Eregon (Benoit Daloze) * Status: Open * Priority: Normal ---------------------------------------- I believe the best way to solve ReDoS is to ensure all Regexps used in the process are linear. Using `Regexp.timeout = 5.0` or so does not really prevent ReDoS, given enough requests causing that timeout the servers will still be very unresponsive. To this purpose, we should make it easy to identify non-linear Regexps and fix them. I suggest we either use 1. a performance warning (enabled with `Warning[:performance] = true`, #19538) or 2. a new regexp warning category (enabled with `Warning[:regexp] = true`). I think we should warn only once per non-linear Regexp, to avoid too many such warnings. We could warn as soon as the Regexp is created, or on first match. On first match might makes more sense for Ruby implementations which compile the Regexp lazily (since that is costly during startup), and also avoids warning for Regexps which are never used (which can be good or bad). OTOH, if the warning is enabled, we could always compile the Regexp eagerly (or at least checks whether it's linear), and that would then provide a better way to guarantee that all Regexps created so far are linear. Because warnings are easily customizable, it is also possible to e.g. `raise/abort` on such a warning, if one wants to ensure their application does not use a non-linear Regexp and so cannot be vulnerable to ReDoS: ```ruby Warning.extend Module.new { def warn(message, category: nil, **) raise message if category == :regexp super end } ``` A regexp warning category seems better for that as it makes it easy to filter by category, if a performance warning one would need to match the message which is less clean. As a note, TruffleRuby already has a similar warning, as a command-line option: ``` $ truffleruby --experimental-options --warn-truffle-regex-compile-fallback -e 'Gem' truffleruby-dev/lib/mri/rubygems/version.rb:176: warning: Regexp /\A\s*([0-9]+(?>\.[0-9a-zA-Z]+)*(-[0-9A-Za-z-]+(\.[0-9A-Za-z-]+)*)?)?\s*\z/ at_start=false encoding=US-ASCII requires backtracking and will not match in linear time truffleruby-dev/lib/mri/rubygems/requirement.rb:105: warning: Regexp /\A\s*(=|!=|>|<|>=|<=|~>)?\s*([0-9]+(?>\.[0-9a-zA-Z]+)*(-[0-9A-Za-z-]+(\.[0-9A-Za-z-]+)*)?)\s*\z/ at_start=false encoding=US-ASCII requires backtracking and will not match in linear time ``` So the warning message could be like `FILE:LINE: warning: Regexp /REGEXP/ requires backtracking and might not match in linear time and might cause ReDoS` or more concise: `FILE:LINE: warning: Regexp /REGEXP/ requires backtracking and might cause ReDoS` -- https://bugs.ruby-lang.org/

5 10

[ruby-core:114757] [Ruby master Bug#9115] Logger traps all exceptions; breaks Timeout
by Eregon (Benoit Daloze) 14 Sep '23

14 Sep '23

Issue #9115 has been updated by Eregon (Benoit Daloze). mame (Yusuke Endoh) wrote in #note-11: > As a better-than-nothing mitigation, it is proposed to enclose the entire `Logger::LogDevice#write` in `Thread.handle_interrupt(:never) { ... }`. > It could be a problem if the method takes a very long time because `Timeout.timeout` cannot interrupt the execution, but such a case will be rare (hopefully). This sounds problematic, especially since that is doing IO, possibly even network IO (e.g. NFS, or logging over some API). I believe all libraries should only catch specific errors they want to rescue and if that's hard to determine than StandardError at most, never Exception. Rescuing Exception without re-raise is always a bug (e.g. NoMemoryError/SystemStackError can be silent and that can cause pretty serious inconsistencies and indirectly what looks like memory corruption). ---------------------------------------- Bug #9115: Logger traps all exceptions; breaks Timeout https://bugs.ruby-lang.org/issues/9115#change-104594 * Author: cphoenix (Chris Phoenix) * Status: Assigned * Priority: Normal * Assignee: sonots (Naotoshi Seo) * ruby -v: ruby 2.0.0p247 (2013-06-27) [i386-mingw32] ---------------------------------------- Line 577-579 of logger.rb rescue Exception => ignored warn("log writing failed. #{ignored}") end Thus, when the system times out in the middle of writing a log message, it warns "log writing failed. execution expired" and just keeps right on running. This is true in 1.9.3 as well. I haven't looked at older versions. Pardon me while I go grep "rescue Exception" in the entire Ruby codebase, and see whether I can reliably use Timeout at all... OK, you might check out C:\Ruby200\lib\ruby\gems\2.0.0\gems\activerecord-3.2.13\lib\active_record\railties\databases.rake All the other "rescue Exception" seem to re-raise it, except maybe C:\Ruby200\lib\ruby\2.0.0\xmlrpc\server.rb and C:\Ruby200\lib\ruby\gems\2.0.0\gems\activesupport-3.2.13\lib\active_support\callbacks.rb -- https://bugs.ruby-lang.org/

1 0