{"action":"created","issue":{"url":"https://api.github.com/repos/FluxML/Flux.jl/issues/828","repository_url":"https://api.github.com/repos/FluxML/Flux.jl","labels_url":"https://api.github.com/repos/FluxML/Flux.jl/issues/828/labels{/name}","comments_url":"https://api.github.com/repos/FluxML/Flux.jl/issues/828/comments","events_url":"https://api.github.com/repos/FluxML/Flux.jl/issues/828/events","html_url":"https://github.com/FluxML/Flux.jl/issues/828","id":475427651,"node_id":"MDU6SXNzdWU0NzU0Mjc2NTE=","number":828,"title":"Flux Allocates Excessively","user":{"login":"jmulcahy","id":6724499,"node_id":"MDQ6VXNlcjY3MjQ0OTk=","avatar_url":"https://avatars3.githubusercontent.com/u/6724499?v=4","gravatar_id":"","url":"https://api.github.com/users/jmulcahy","html_url":"https://github.com/jmulcahy","followers_url":"https://api.github.com/users/jmulcahy/followers","following_url":"https://api.github.com/users/jmulcahy/following{/other_user}","gists_url":"https://api.github.com/users/jmulcahy/gists{/gist_id}","starred_url":"https://api.github.com/users/jmulcahy/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jmulcahy/subscriptions","organizations_url":"https://api.github.com/users/jmulcahy/orgs","repos_url":"https://api.github.com/users/jmulcahy/repos","events_url":"https://api.github.com/users/jmulcahy/events{/privacy}","received_events_url":"https://api.github.com/users/jmulcahy/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":9,"created_at":"2019-08-01T01:37:56Z","updated_at":"2019-08-25T01:12:41Z","closed_at":null,"author_association":"NONE","body":"Flux is allocating quite a bit during calls to the AD, like in gradient. For example, on the Zygote branch with Zygote master:\r\n\r\n```\r\njulia> function test_zygote()\r\n       t = ones(1, 1, 1, 1)\r\n       f = Conv((1, 1), 1=>1)\r\n       ps = params(f)\r\n       Zygote.gradient(() -> sum(f(t)), ps)\r\n       end\r\ntest_zygote (generic function with 1 method)\r\n\r\njulia> test_zygote()\r\nGrads(...)\r\n\r\njulia> @time test_zygote()\r\n  0.000771 seconds (857 allocations: 35.641 KiB)\r\nGrads(...)\r\n```\r\n\r\nBigger input doesn't sufficiently amortize the cost, either.\r\n```\r\njulia> function test_zygote_big()\r\n       t = ones(200, 200, 1, 1)\r\n       f = Conv((1, 1), 1=>1)\r\n       ps = params(f)\r\n       Zygote.gradient(() -> sum(f(t)), ps)\r\n       end\r\ntest_zygote_big (generic function with 1 method)\r\n\r\njulia> test_zygote_big()\r\nGrads(...)\r\n\r\njulia> @time test_zygote_big()\r\n  0.650714 seconds (5.48 M allocations: 191.705 MiB, 6.02% gc time)\r\nGrads(...)\r\n```\r\n\r\nTracker is doing the same thing:\r\n```\r\njulia> function test_tracker_big()\r\n       t = ones(200, 200, 1, 1)\r\n       f = Conv((1, 1), 1=>1)\r\n       ps = params(f)\r\n       Flux.Tracker.gradient(() -> sum(f(t)), ps)\r\n       end\r\ntest_tracker_big (generic function with 1 method)\r\n\r\njulia> test_tracker_big()\r\nGrads(...)\r\n\r\n\r\njulia> @time test_tracker_big()\r\n  0.600915 seconds (5.36 M allocations: 189.873 MiB, 7.95% gc time)\r\nGrads(...)\r\n```\r\n It looks like there are some issues with type stability:\r\n```\r\njulia> function test_zygote_big()\r\n       t = ones(200, 200, 1, 1)\r\n       f = Conv((1, 1), 1=>1)\r\n       ps = params(f)\r\n       @code_warntype Zygote.gradient(() -> sum(f(t)), ps)\r\n       end\r\ntest_zygote_big (generic function with 1 method)\r\n\r\njulia> test_zygote_big()\r\nBody::Zygote.Grads\r\n1 ─ %1  = (getfield)(args, 1)::Params\r\n│   %2  = Zygote.nothing::Nothing\r\n│   %3  = Zygote.nothing::Nothing\r\n│   %4  = %new(Zygote.Context, %2, %3)::Zygote.Context\r\n│   %5  = invoke Zygote._forward(%4::Zygote.Context, _2::getfield(Main, Symbol(\"##9#10\")){Array{Float64,4},Conv{2,4,typeof(identity),Array{Float32,4},Array{Float32,1}}})::Tuple{Any,typeof(∂(λ))}\r\n│   %6  = (Base.getfield)(%5, 1)::Any\r\n│   %7  = (Base.getfield)(%5, 2)::typeof(∂(λ))\r\n│   %8  = Zygote.:(##42#43)::Type{getfield(Zygote, Symbol(\"##42#43\"))}\r\n│   %9  = (Core.typeof)(%7)::Type{#s70} where #s70<:typeof(∂(λ)) where _1\r\n│   %10 = (Core.apply_type)(%8, Params, Zygote.Context, %9)::Type{getfield(Zygote, Symbol(\"##42#43\")){Params,Zygote.Context,_1}} where _1\r\n│   %11 = %new(%10, %1, %4, %7)::getfield(Zygote, Symbol(\"##42#43\")){Params,Zygote.Context,_1} where _1\r\n│   %12 = (Zygote.sensitivity)(%6)::Any\r\n│   %13 = (%11)(%12)::Zygote.Grads\r\n└──       return %13\r\n```\r\nI suspect the large number of allocations are at least a contributing factor to https://github.com/FluxML/Flux.jl/issues/736 and the corresponding CuArrays issue https://github.com/JuliaGPU/CuArrays.jl/issues/323. That problem makes it very difficult/annoying to train some large networks.\r\n"},"comment":{"url":"https://api.github.com/repos/FluxML/Flux.jl/issues/comments/524592030","html_url":"https://github.com/FluxML/Flux.jl/issues/828#issuecomment-524592030","issue_url":"https://api.github.com/repos/FluxML/Flux.jl/issues/828","id":524592030,"node_id":"MDEyOklzc3VlQ29tbWVudDUyNDU5MjAzMA==","user":{"login":"jmulcahy","id":6724499,"node_id":"MDQ6VXNlcjY3MjQ0OTk=","avatar_url":"https://avatars3.githubusercontent.com/u/6724499?v=4","gravatar_id":"","url":"https://api.github.com/users/jmulcahy","html_url":"https://github.com/jmulcahy","followers_url":"https://api.github.com/users/jmulcahy/followers","following_url":"https://api.github.com/users/jmulcahy/following{/other_user}","gists_url":"https://api.github.com/users/jmulcahy/gists{/gist_id}","starred_url":"https://api.github.com/users/jmulcahy/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jmulcahy/subscriptions","organizations_url":"https://api.github.com/users/jmulcahy/orgs","repos_url":"https://api.github.com/users/jmulcahy/repos","events_url":"https://api.github.com/users/jmulcahy/events{/privacy}","received_events_url":"https://api.github.com/users/jmulcahy/received_events","type":"User","site_admin":false},"created_at":"2019-08-25T01:12:41Z","updated_at":"2019-08-25T01:12:41Z","author_association":"NONE","body":"For comparison purposes, here is an example model that keeps slowing down during training, but it never becomes abruptly worse. Maybe these are two separate issues? The slowdown is still linked to the GC.\r\n\r\n```\r\nusing CuArrays, Flux, IterTools\r\n\r\nfunction make_model1()\r\n    first_layer = Conv((1, 1), 1=>16)\r\n\r\n    # performance becomes very bad during the 8th epoch\r\n    layers = [Conv((3, 3), 16=>16, pad=(1, 1)) for _ in 1:50]\r\n    last_layer = Conv((1, 1), 16=>1)\r\n\r\n    Chain(first_layer, layers..., last_layer) |> gpu\r\nend\r\n\r\nfunction make_model2()\r\n    # performance slowly becomes worse, but not suddenly so\r\n    layers = [Conv((3, 3), 1=>1, pad=(1, 1)) for _ in 1:50]\r\n\r\n    Chain(layers...) |> gpu\r\nend\r\n\r\nfunction test_training()\r\n    model = make_model2()\r\n\r\n    data = collect(repeatedly(() -> (CuArrays.randn(200, 200, 1, 1), CuArrays.randn(200, 200, 1, 1)), 2500))\r\n\r\n    loss(x, y) = sum(model(y) - x)\r\n    opt = ADAM()\r\n    ps = params(model)\r\n\r\n    epoch = 1\r\n    while true\r\n        @info \"Epoch $epoch\"\r\n        CuArrays.pool_timings!()\r\n        CuArrays.@time Flux.train!(loss, ps, data, opt)\r\n        CuArrays.pool_timings()\r\n        epoch += 1\r\n    end\r\nend\r\n\r\ntest_training()\r\n```\r\n\r\n```\r\n[ Info: Epoch 1\r\n137.232261 seconds (258.23 M CPU allocations: 13.105 GiB, 5.25% gc time) (1.89 M GPU allocations: 95.019 GiB, 2.83% gc time of which 2.82% spent allocating)\r\n ────────────────────────────────────────────────\r\n                                   Time\r\n                           ──────────────────────\r\n     Tot / % measured:           138s / 1.03%\r\n\r\n Section           ncalls     time   %tot     avg\r\n ────────────────────────────────────────────────\r\n background task       97    989ms  69.8%  10.2ms\r\n   reclaim             97   32.4ms  2.29%   334μs\r\n   scan                97   88.9μs  0.01%   917ns\r\n pooled alloc       1.89M    442ms  31.2%   234ns\r\n   1 try alloc      2.94k   77.7ms  5.49%  26.5μs\r\n ────────────────────────────────────────────────\r\n[ Info: Epoch 2\r\n128.520860 seconds (215.66 M CPU allocations: 10.894 GiB, 7.72% gc time) (1.89 M GPU allocations: 95.019 GiB, 3.23% gc time of which 3.25% spent allocating)\r\n ────────────────────────────────────────────────\r\n                                   Time\r\n                           ──────────────────────\r\n     Tot / % measured:           129s / 1.62%\r\n\r\n Section           ncalls     time   %tot     avg\r\n ────────────────────────────────────────────────\r\n background task       96    1.66s  79.7%  17.3ms\r\n   reclaim             96   82.7ms  3.97%   862μs\r\n   scan                96   87.9μs  0.00%   916ns\r\n pooled alloc       1.89M    423ms  20.3%   224ns\r\n   1 try alloc      3.96k   53.6ms  2.57%  13.5μs\r\n ────────────────────────────────────────────────\r\n[ Info: Epoch 3\r\n131.765121 seconds (215.66 M CPU allocations: 10.861 GiB, 10.67% gc time) (1.89 M GPU allocations: 95.019 GiB, 3.11% gc time of which 0.10% spent allocating)\r\n ────────────────────────────────────────────────\r\n                                   Time\r\n                           ──────────────────────\r\n     Tot / % measured:           132s / 2.04%\r\n\r\n Section           ncalls     time   %tot     avg\r\n ────────────────────────────────────────────────\r\n background task       96    2.32s  86.2%  24.1ms\r\n   reclaim             96   3.45ms  0.13%  36.0μs\r\n   scan                96   91.6μs  0.00%   955ns\r\n pooled alloc       1.89M    370ms  13.8%   196ns\r\n   1 try alloc         35    662μs  0.02%  18.9μs\r\n ────────────────────────────────────────────────\r\n[ Info: Epoch 4\r\n132.402783 seconds (215.66 M CPU allocations: 10.928 GiB, 14.39% gc time) (1.89 M GPU allocations: 95.019 GiB, 2.94% gc time of which 0.23% spent allocating)\r\n ────────────────────────────────────────────────\r\n                                   Time\r\n                           ──────────────────────\r\n     Tot / % measured:           132s / 2.59%\r\n\r\n Section           ncalls     time   %tot     avg\r\n ────────────────────────────────────────────────\r\n background task       96    3.05s  88.9%  31.8ms\r\n   reclaim             96   6.46ms  0.19%  67.3μs\r\n   scan                96   83.0μs  0.00%   864ns\r\n pooled alloc       1.89M    380ms  11.1%   201ns\r\n   1 try alloc        191   2.51ms  0.07%  13.2μs\r\n ────────────────────────────────────────────────\r\n[ Info: Epoch 5\r\n136.397199 seconds (215.66 M CPU allocations: 10.861 GiB, 17.50% gc time) (1.89 M GPU allocations: 95.019 GiB, 2.90% gc time of which 0.10% spent allocating)\r\n ────────────────────────────────────────────────\r\n                                   Time\r\n                           ──────────────────────\r\n     Tot / % measured:           136s / 3.18%\r\n\r\n Section           ncalls     time   %tot     avg\r\n ────────────────────────────────────────────────\r\n background task       96    3.97s  91.5%  41.4ms\r\n   reclaim             96   3.26ms  0.08%  33.9μs\r\n   scan                96   78.5μs  0.00%   817ns\r\n pooled alloc       1.89M    368ms  8.48%   195ns\r\n   1 try alloc         46    859μs  0.02%  18.7μs\r\n ────────────────────────────────────────────────\r\n[ Info: Epoch 6\r\n141.585927 seconds (215.67 M CPU allocations: 10.862 GiB, 20.06% gc time) (1.89 M GPU allocations: 95.019 GiB, 2.83% gc time of which 0.08% spent allocating)\r\n ────────────────────────────────────────────────\r\n                                   Time\r\n                           ──────────────────────\r\n     Tot / % measured:           142s / 3.59%\r\n\r\n Section           ncalls     time   %tot     avg\r\n ────────────────────────────────────────────────\r\n background task       96    4.70s  92.6%  49.0ms\r\n   reclaim             96   2.84ms  0.06%  29.6μs\r\n   scan                96   82.5μs  0.00%   859ns\r\n pooled alloc       1.89M    377ms  7.43%   200ns\r\n   1 try alloc         40    642μs  0.01%  16.0μs\r\n ────────────────────────────────────────────────\r\n```\r\n...many epoch's later...\r\n```\r\n[ Info: Epoch 47\r\n447.433371 seconds (215.67 M CPU allocations: 10.865 GiB, 73.17% gc time) (1.89 M GPU allocations: 95.019 GiB, 0.92% gc time of which 3.11% spent allocating)\r\n ────────────────────────────────────────────────\r\n                                   Time\r\n                           ──────────────────────\r\n     Tot / % measured:           447s / 74.2%\r\n\r\n Section           ncalls     time   %tot     avg\r\n ────────────────────────────────────────────────\r\n background task       96     331s   100%   3.45s\r\n   reclaim             96   62.5ms  0.02%   651μs\r\n   scan                96   94.4μs  0.00%   983ns\r\n pooled alloc       1.89M    469ms  0.14%   248ns\r\n   1 try alloc      3.02k   65.8ms  0.02%  21.8μs\r\n ────────────────────────────────────────────────\r\n[ Info: Epoch 48\r\n455.582128 seconds (215.67 M CPU allocations: 10.865 GiB, 73.56% gc time) (1.89 M GPU allocations: 95.019 GiB, 0.90% gc time of which 3.09% spent allocating)\r\n ────────────────────────────────────────────────\r\n                                   Time\r\n                           ──────────────────────\r\n     Tot / % measured:           456s / 74.6%\r\n\r\n Section           ncalls     time   %tot     avg\r\n ────────────────────────────────────────────────\r\n background task       96     339s   100%   3.53s\r\n   reclaim             96   62.0ms  0.02%   646μs\r\n   scan                96   93.6μs  0.00%   975ns\r\n pooled alloc       1.89M    454ms  0.13%   240ns\r\n   1 try alloc      3.02k   65.3ms  0.02%  21.6μs\r\n ────────────────────────────────────────────────\r\n[ Info: Epoch 49\r\n465.005904 seconds (215.67 M CPU allocations: 10.865 GiB, 73.97% gc time) (1.89 M GPU allocations: 95.019 GiB, 0.89% gc time of which 3.15% spent allocating)\r\n ────────────────────────────────────────────────\r\n                                   Time\r\n                           ──────────────────────\r\n     Tot / % measured:           465s / 75.0%\r\n\r\n Section           ncalls     time   %tot     avg\r\n ────────────────────────────────────────────────\r\n background task       96     348s   100%   3.63s\r\n   reclaim             96   66.0ms  0.02%   688μs\r\n   scan                96   93.4μs  0.00%   973ns\r\n pooled alloc       1.89M    455ms  0.13%   241ns\r\n   1 try alloc      3.02k   64.5ms  0.02%  21.3μs\r\n ────────────────────────────────────────────────\r\n```"}}
{"actor":{"display_login":"jmulcahy"}}