Riak-cs-gc issue after huge deletes, no gc progress after days, crash reports for riak-cs [JIRA: RCS-333]

[th-m-vogel]

During riak-cs tests I uploaded and deleted a huge number of files, including a lot of large files. Riak-cs-gc does timeout now cleaning up these files. It looks like gc is progressing on deleting, but extremely slow.

OS: Debian 7 RiakCS Version: 1.4.1, 1.4.2 (binary release) and riak-cs_1.4.2.2.g6f8bcc0-1_amd64.deb build from src RiakVersion: 1.4.2 binary release for Debian

** When State == deleting
**      Data  == {state,<<"test">>,<<"Big/Downloads/Visual Studio 2012/2012-Professional/packages/dotNetFramework/dotNetFx45_Full_x86_x64.exe">>,<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,{lfs_manifest_v3,3,1048576,{<<"test">>,<<"Big/Downloads/Visual Studio 2012/2012-Professional/packages/dotNetFramework/dotNetFx45_Full_x86_x64.exe">>},[{"x-amz-meta-cb-modifiedtime","Fri, 18 Oct 2013 09:47:27 GMT"}],"2013-10-18T18:00:39.000Z",<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,50349920,<<"application/octet-stream">>,<<165,232,29,27,57,5,173,160,166,227,95,214,198,162,225,244>>,scheduled_delete,{1382,119239,842368},{1382,119243,73728},[],{1382,122461,251983},{1382,313632,472432},[{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,28},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,29},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,30},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,31},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,32},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,33},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,34},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,35},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,36},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,37},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,38},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,39},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,40},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,41},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,42},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,43},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,44},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,45},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,46},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,47},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,48}],undefined,{acl_v2,{"test","8c3221fc3eb97243faa351cb333b7556d3c81f63edffe9ec86e3c8698a140083","6MOZOHJLKH6Y15OZUINV"},[{{"test","8c3221fc3eb97243faa351cb333b7556d3c81f63edffe9ec86e3c8698a140083"},['FULL_CONTROL']}],{1382,119239,841966}},[{deleted,true}],undefined},<0.13775.70>,[{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,29},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,30},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,31},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,32},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,33},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,34},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,35},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,36},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,37},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,38},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,39},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,40},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,41},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,42},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,43},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,44},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,45},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,46},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,47},{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,48}],[{<<114,124,234,140,11,144,78,204,156,253,217,136,115,52,242,46>>,28}],[<0.13793.70>],[],28,49}
** Reason for termination =
** timeout
2013-10-21 00:01:32 =CRASH REPORT====
  crasher:
    initial call: riak_cs_delete_fsm:init/1
    pid: <0.13792.70>
    registered_name: []
    exception exit: {timeout,[{gen_fsm,terminate,7,[{file,"gen_fsm.erl"},{line,611}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,227}]}]}
    ancestors: [riak_cs_delete_fsm_sup,riak_cs_sup,<0.128.0>]
    messages: []
    links: [<0.10874.70>,<0.277.0>]
    dictionary: []
    trap_exit: false
    status: running
    heap_size: 1597
    stack_size: 24
    reductions: 1500
  neighbours:
    neighbour: [{pid,<0.13775.70>},{registered_name,[]},{initial_call,{riakc_pb_socket,init,['Argument__1']}},{current_function,{gen_server,loop,6}},{ancestors,[riak_cs_gc_d,riak_cs_sup,<0.128.0>]},{messages,[]},{links,[<0.10874.70>]},{dictionary,[]},{trap_exit,false},{status,waiting},{heap_size,2103540},{stack_size,9},{reductions,4852421}]
    neighbour: [{pid,<0.10874.70>},{registered_name,riak_cs_gc_d},{initial_call,{riak_cs_gc_d,init,['Argument__1']}},{current_function,{gen,do_call,4}},{ancestors,[riak_cs_sup,<0.128.0>]},{messages,[{#Ref<0.0.49.202171>,{error,disconnected}}]},{links,[<0.13775.70>,<0.13792.70>,<0.132.0>]},{dictionary,[]},{trap_exit,false},{status,runnable},{heap_size,1682835},{stack_size,39},{reductions,2748}]
2013-10-21 00:01:32 =SUPERVISOR REPORT====
     Supervisor: {local,riak_cs_delete_fsm_sup}
     Context:    child_terminated
     Reason:     timeout
     Offender:   [{pid,<0.13792.70>},{name,undefined},{mfargs,{riak_cs_delete_fsm,start_link,undefined}},{restart_type,temporary},{shutdown,2000},{child_type,worker}]

2013-10-21 00:01:32 =SUPERVISOR REPORT====
     Supervisor: {local,riak_cs_sup}
     Context:    child_terminated
     Reason:     timeout
     Offender:   [{pid,<0.10874.70>},{name,riak_cs_gc_d},{mfargs,{riak_cs_gc_d,start_link,[]}},{restart_type,permanent},{shutdown,5000},{child_type,worker}]

[kellymclaughlin]

Thanks for the report! The GC subsystem performance is one of our primary areas of focus for the next release. We have had several users report this same problem and we will be addressing it very soon.

[shino]

Not a root cause but riak_cs_block_server:constrained_delete/3 executes DELETE with options R=PR=W=PW=all [1]. If one Riak node goes very slow, this DELETE call may result in timeout.

Can this strong constraint be weakened? For example, is PR=PW=quorum better choice?

[1] https://github.com/basho/riak_cs/blob/release/1.4/src/riak_cs_block_server.erl#L378

[shino]

Sorry for long silence. Riak CS, at version 1.5, introduced concurrent GC feature. It may help improve GC performance. Please note that concurrency > 1 may make performance worse when OS resource, e.g. disk or network, is bottleneck.

I will close this issue because it's for old version of riak cs, but please feel free to reopen or open new issue with new findings.

Thanks again for reporting!