Redmine

Any suggestions for troubleshooting? Is there anything I can do to find a more meaningful error message?

I've discovered a new symptom. I was looking at /var/log/messages for another reason and noticed that Ruby had been invoking oom-killer.

I started up top and went to the page causing the error. At first svn and mysqld showed activity for a few seconds and then ruby went to 100% cpu and started consuming memory. It started at about 2% and didn't stop until it crashed at 85%+ of 4GB. The internal server error pops up at that point.

bump, still experiencing this problem

No exception stack if you run WEBrick in debug mode (-B switch, if I remember well) ?

Are you sure it's -B?

root@redmine:/usr/share/redmine# ruby script/server -B
server: invalid option: -B

I found another symptom. If I try to update the repos offline, I get the same behavior (ruby using 100% CPU and consuming memory until oom-killer steps in):

root@redmine:/usr/share/redmine# ruby script/runner "Repository.fetch_changesets" -e production
Killed

Was -B for mongrel, my mistake.

You can change logging level in config/environments/production.rb :

config.log_level = :debug

Even with debug logging enabled nothing gets logged when I try to access the repository page, the process just gets killed in the same way I've described.

Do you get a core dump ?

I don't see one in std streams or the redmine production or development log or in syslog or messages. Would it be somewhere else? Would the call trace be helpful? It doesn't look that helpful...

To get the stack trace.

Mar 8 12:23:50 redmine kernel: [12104.250221] ruby invoked oom-killer: gfp_mask=0x201da, order=0, oom_adj=0
Mar 8 12:23:50 redmine kernel: [12104.250235] ruby cpuset=/ mems_allowed=0
Mar 8 12:23:50 redmine kernel: [12104.250245] Pid: 2168, comm: ruby Not tainted 2.6.32-24-server #39-Ubuntu
Mar 8 12:23:50 redmine kernel: [12104.250248] Call Trace:
Mar 8 12:23:51 redmine kernel: [12104.250296] [<ffffffff810b363d>] ? cpuset_print_task_mems_allowed+0x9d/0xb0
Mar 8 12:23:51 redmine kernel: [12104.250312] [<ffffffff810f6e64>] oom_kill_process+0xd4/0x2f0
Mar 8 12:23:51 redmine kernel: [12104.250317] [<ffffffff810f7420>] ? select_bad_process+0xd0/0x110
Mar 8 12:23:51 redmine kernel: [12104.250321] [<ffffffff810f74b8>] __out_of_memory+0x58/0xc0
Mar 8 12:23:51 redmine kernel: [12104.250325] [<ffffffff810f764e>] out_of_memory+0x12e/0x1a0
Mar 8 12:23:51 redmine kernel: [12104.250348] [<ffffffff8155aa3e>] ? _spin_lock+0xe/0x20
Mar 8 12:23:51 redmine kernel: [12104.250353] [<ffffffff810fa6d1>] __alloc_pages_slowpath+0x511/0x580
Mar 8 12:23:51 redmine kernel: [12104.250358] [<ffffffff810fa8b1>] __alloc_pages_nodemask+0x171/0x180
Mar 8 12:23:51 redmine kernel: [12104.250371] [<ffffffff8112d6c7>] alloc_pages_current+0x87/0xd0
Mar 8 12:23:51 redmine kernel: [12104.250376] [<ffffffff810f4637>] __page_cache_alloc+0x67/0x70
Mar 8 12:23:51 redmine kernel: [12104.250385] [<ffffffff810fe209>] __do_page_cache_readahead+0xc9/0x210
Mar 8 12:23:51 redmine kernel: [12104.250390] [<ffffffff810fe371>] ra_submit+0x21/0x30
Mar 8 12:23:51 redmine kernel: [12104.250393] [<ffffffff810f5efe>] filemap_fault+0x3fe/0x450
Mar 8 12:23:51 redmine kernel: [12104.250399] [<ffffffff811126c4>] __do_fault+0x54/0x500
Mar 8 12:23:51 redmine kernel: [12104.250403] [<ffffffff81115c08>] handle_mm_fault+0x1a8/0x3c0
Mar 8 12:23:51 redmine kernel: [12104.250407] [<ffffffff81117e55>] ? remove_vma+0x65/0x80
Mar 8 12:23:51 redmine kernel: [12104.250412] [<ffffffff8155d5b5>] do_page_fault+0x125/0x3b0
Mar 8 12:23:51 redmine kernel: [12104.250416] [<ffffffff8155af05>] page_fault+0x25/0x30
Mar 8 12:23:51 redmine kernel: [12104.250419] Mem-Info:
Mar 8 12:23:51 redmine kernel: [12104.250422] Node 0 DMA per-cpu:
Mar 8 12:23:51 redmine kernel: [12104.250425] CPU 0: hi: 0, btch: 1 usd: 0
Mar 8 12:23:51 redmine kernel: [12104.250427] Node 0 DMA32 per-cpu:
Mar 8 12:23:51 redmine kernel: [12104.250431] CPU 0: hi: 186, btch: 31 usd: 178
Mar 8 12:23:51 redmine kernel: [12104.250437] active_anon:220136 inactive_anon:22536 isolated_anon:0
Mar 8 12:23:51 redmine kernel: [12104.250438] active_file:64 inactive_file:38 isolated_file:0
Mar 8 12:23:51 redmine kernel: [12104.250439] unevictable:0 dirty:0 writeback:0 unstable:0
Mar 8 12:23:51 redmine kernel: [12104.250440] free:2000 slab_reclaimable:689 slab_unreclaimable:2015
Mar 8 12:23:51 redmine kernel: [12104.250442] mapped:112 shmem:11373 pagetables:1795 bounce:0
Mar 8 12:23:51 redmine kernel: [12104.250444] Node 0 DMA free:4036kB min:60kB low:72kB high:88kB active_anon:11576kB inactive_anon:256kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15312kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:4kB kernel_stack:0kB pagetables:24kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:64 all_unreclaimable? yes
Mar 8 12:23:51 redmine kernel: [12104.250457] lowmem_reserve[]: 0 994 994 994
Mar 8 12:23:51 redmine kernel: [12104.250462] Node 0 DMA32 free:3964kB min:4000kB low:5000kB high:6000kB active_anon:868968kB inactive_anon:89888kB active_file:256kB inactive_file:152kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:1018016kB mlocked:0kB dirty:0kB writeback:0kB mapped:448kB shmem:45492kB slab_reclaimable:2756kB slab_unreclaimable:8056kB kernel_stack:840kB pagetables:7156kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:617 all_unreclaimable? yes
Mar 8 12:23:51 redmine kernel: [12104.250475] lowmem_reserve[]: 0 0 0 0
Mar 8 12:23:51 redmine kernel: [12104.250480] Node 0 DMA: 1*4kB 2*8kB 3*16kB 2*32kB 3*64kB 1*128kB 2*256kB 0*512kB 1*1024kB 1*2048kB 0*4096kB = 4036kB
Mar 8 12:23:51 redmine kernel: [12104.250497] Node 0 DMA32: 21*4kB 1*8kB 0*16kB 1*32kB 0*64kB 0*128kB 1*256kB 1*512kB 1*1024kB 1*2048kB 0*4096kB = 3964kB
Mar 8 12:23:51 redmine kernel: [12104.250513] 11487 total pagecache pages
Mar 8 12:23:51 redmine kernel: [12104.250515] 0 pages in swap cache
Mar 8 12:23:51 redmine kernel: [12104.250522] Swap cache stats: add 0, delete 0, find 0/0
Mar 8 12:23:51 redmine kernel: [12104.250524] Free swap = 0kB
Mar 8 12:23:51 redmine kernel: [12104.250526] Total swap = 0kB
Mar 8 12:23:51 redmine kernel: [12104.257967] 262128 pages RAM
Mar 8 12:23:51 redmine kernel: [12104.257972] 6292 pages reserved
Mar 8 12:23:51 redmine kernel: [12104.257974] 16969 pages shared
Mar 8 12:23:51 redmine kernel: [12104.257976] 247176 pages non-shared
Mar 8 12:23:51 redmine kernel: [12104.257981] Out of memory: kill process 2168 (ruby) score 109350 or a child
Mar 8 12:23:51 redmine kernel: [12104.380239] Killed process 2168 (ruby)

Is there any other information I can find or provide? Thanks for the assistance.

It's a workaround but I'd like to find the source of this issue, as this looks to be the same as #633 which is still open.

Somehow related to http://redmine.ruby-lang.org/issues/4293 ?

redmine is reliably eating all of system memory when accessing a svn repo with fetch_changeset. Specifically, it fails on any of several changes which include 10,000+ files (e.g. checking in big third-party source trees.) There's something specifically about the size of the changeset which seems to be making it fail.

Dialing the identifier increment down didn't help at all --- small changesets don't bother it, but the giant ones choke it dead.

Ubuntu versions:
sqlite3 3.6.22
ruby 1.8.7.302
rails 2.3.11
redmine 1.2.0
svn 1.6.6

Here's an example run at the command line, with a little debugging info added:
Fetching changes from 8133
Fetching changes from 8134
Fetching changes from 8135 <------ this is the giant one --- about 34,000 files added. It completes, but then...
Fetching changes from 8136
/usr/share/redmine/vendor/rails/railties/lib/commands/runner.rb:48: /usr/share/redmine/lib/redmine/scm/adapters/abstract_adapter.rb:213:in `popen': Cannot allocate memory - 'svn' log --xml -r 8136:8136 --username 'jhbrown' --password ELIDEDFORBUG --no-auth-cache --non-interactive --verbose 'svn://localhost:3691//' (Errno::ENOMEM)
from /usr/share/redmine/lib/redmine/scm/adapters/abstract_adapter.rb:213:in `shellout'
from /usr/share/redmine/lib/redmine/scm/adapters/abstract_adapter.rb:194:in `shellout'
from /usr/share/redmine/lib/redmine/scm/adapters/subversion_adapter.rb:170:in `revisions'
from /usr/share/redmine/app/models/repository/subversion.rb:67:in `fetch_changesets'
from /usr/lib/ruby/1.8/active_record/associations/association_proxy.rb:215:in `send'
from /usr/lib/ruby/1.8/active_record/associations/association_proxy.rb:215:in `method_missing'
from /usr/share/redmine/app/models/repository.rb:243:in `fetch_changesets'
from /usr/share/redmine/app/models/repository.rb:240:in `each'
from /usr/share/redmine/app/models/repository.rb:240:in `fetch_changesets'
from (eval):1
from /usr/lib/ruby/1.8/rubygems/custom_require.rb:31:in `eval'
from /usr/share/redmine/vendor/rails/railties/lib/commands/runner.rb:48
from /usr/lib/ruby/1.8/rubygems/custom_require.rb:31:in `gem_original_require'
from /usr/lib/ruby/1.8/rubygems/custom_require.rb:31:in `require'
from script/runner:3

Closing this, status is resolved since 400 days and more (issue was last updated more than 400 days ago)...

I am seeing this issue right now in 1.3.1 -- this doesn't seem fixed to me.

The current Redmine version is 2.3. Please upgrade your Redmine.

Upgrading to 2.3 didn't solve the problem.

Not sure if this should go into a new ticket, but in our case it looks like the root problem is the diff functionality -- for a very large changeset, SubversionAdapter::diff reads the entire diff into memory (we have some that are hundreds of megabytes), which chews up an enormous amount of memory that doesn't seem to get returned to the system. (Ruby may GC it internally, but external programs like svn and sendmail fail.)

For the standard diffs based on UnifiedDiff (inline and side-by-side) this content gets truncated after a set number of lines, so I tried using that value in SubversionAdapter::diff to limit the number of lines read from svn, and the problem disappeared.

          # Load more than the max so that an overflow is detected
          max_lines = Setting.diff_max_lines_displayed.to_i + 10
          shellout(cmd) do |io|
            io.each_line do |line|
              diff << line
              return diff if diff.length > max_lines
            end
          end

The only problem with this is that there's also a "unified" diff, which returns the full, raw diff. I think this is just the svn command output, so in theory it could be just piped back to the user without reading the whole thing into memory, but it seems like that would require the base Adapter::diff API to change so that it returns something other than an array.

Not sure if exactly the same issue but I also get Ruby/Redmine using up all my memory when trying to view a large repository for the first time. After a while it gets killed and I get a 500 Apache error:

Jul 26 13:12:42 redmine kernel: [6139889.588711] apache2 invoked oom-killer: gfp_mask=0x201da, order=0, oom_adj=0, oom_score_adj=0
...
Jul 26 13:12:42 redmine kernel: [6139889.591117] Out of memory: Kill process 330 (ruby) score 805 or sacrifice child
Jul 26 13:12:42 redmine kernel: [6139889.591133] Killed process 330 (ruby) total-vm:1650732kB, anon-rss:586792kB, file-rss:0kB

I can't find any entry in Redmine's production.log with debug level enabled.

I have a smaller repository on the same server with the exact same settings except for the address (both access via file:///) and it's working fine.

http://www.redmine.org/boards/2/topics/37916

Reposting my post from the link above here.

This out of memory problem completely blocks the use of the repository feature for us so it's a major disturbance.

I have two svn repositories sitting in the same location on the same server as Redmine. Both are configured identically with the file:// location in Redmine. One repository works fine, but the other shows a 500 error after a minute when trying to browse. I'm assuming this is because it has a much larger revision count (4600 vs 500). I've tried refreshing multiple times hoping that this would eventually load the data but it's not working. I've run rails runner "Repository.fetch_changesets" -e production every hour overnight and it doesn't help.

How do I find out what's happening and deal with this? I've seen older posts about editing the changesets volume grabbed each time (or something) but the subversion adapter has changed since then.

This is Redmine 2.3.1.

This is what I get in the apache log:

[Mon May 20 10:33:55 2013] [error] [client xxx.xx.xx.xxx] Premature end of script headers: projects, referer: http://redmine.ourdomain.com/projects/myproject/repository
    [ pid=16991 file=ext/apache2/Hooks.cpp:684 time=2013-05-20 10:33:56.204 ]:
    The backend application (process 17936) did not send a valid HTTP response; instead, it sent nothing at all. It is possible that it has crashed; please check whether there are crashing bugs in this application.

I try to run ./script/rails runner "Repository.fetch_changesets" -e production and the process just gets Killed after some time:

Oct 23 09:03:16 redmine kernel: [7015239.446418] Out of memory: Kill process 15756 (ruby) score 641 or sacrifice child
Oct 23 09:03:16 redmine kernel: [7015239.446431] Killed process 15756 (ruby) total-vm:1400980kB, anon-rss:369264kB, file-rss:0kB