i915 memory leak

[jbeich]

I'm using Skylake GT2, i915kms, Mesa 17.0.3, intel DDX, SNA. This has been stable for a few months. Adding Option "DRI" "3" (see intel(4)) or switching to modesetting DDX appears to accelerate Wired memory growth eventually leading to a hang. Killing Xserver or unloading i915kms/linuxkpi doesn't help. DRI2 is also affected but less pronounced.

Duplicate of #117 ?

$ pkg install mpv
$ while mpv --no-config --end=0.3 /path/to/movie.mp4; do done
<5 min later>
^C
$ top
last pid: 25793;  load averages:  0.87,  1.82,  1.25  up 0+00:12:37    17:31:37
43 processes:  1 running, 42 sleeping

Mem: 14M Active, 169M Inact, 145M Laundry, 61G Wired, 858M Free
ARC: 1055M Total, 97M MFU, 616M MRU, 1050K Anon, 12M Header, 330M Other
     390M Compressed, 881M Uncompressed, 0.83:1 Ratio, 324M Overhead
Swap: 
[...]
$ ls /tmp/shmfd* | wc -l
    3544
$ du -Ashc /tmp/shmfd* | tail -1
1.7M    total

Where did the memory disappear to?

vmstat -m shows

          Type InUse MemUse HighUse Requests  Size(s)
         linux    29     2K       -       29  64
-        linux  2376   762K       -     7115  16,32,64,128,256,512,1024,2048,4096,8192,16384,32768,65536
- linuxcurrent    68    11K       -       80  64,256
-       dmabuf    12     6K       -       12  512
+        linux 18527 16250K       -   434560  16,32,64,128,256,512,1024,2048,4096,8192,16384,32768,65536
+ linuxcurrent    70    11K       -     3622  64,256
+       dmabuf  3544  1772K       -     3544  512
        lkpifw     0     0K       -        2  32
-          idr   144    71K       -      162  128,512
+          idr   166    82K       -     3745  128,512
           idr     0     0K       -        1  16

while vmstat -z shows

 ITEM                   SIZE  LIMIT     USED     FREE      REQ FAIL SLEEP
-i915_gem_object:        624,      0,     258,     120,     419,   0,   0
-i915_gem_vma:           480,      0,     244,     252,     465,   0,   0
-i915_gem_request:       616,      0,      11,     109,     836,   0,   0
+i915_gem_object:        624,      0,    9108,      84,   45596,   0,   0
+i915_gem_vma:           480,      0,    4677,     259,   37668,   0,   0
+i915_gem_request:       616,      0,    3536,     118,   29398,   0,   0

[weabot]

I also have been experiencing memory issues with amdgpu on a compositor that uses EGL, although I'm using mesa 13. Maybe it's a drm issue?

[iotamudelta]

For amdgpu, we suspect it to be in ttm (which i915 does not use).

[hselasky]

Have you plotted the memory usage stats over time to figure out how much memory leaks per minute?

[Beeblebrox-BSD]

I can confirm the memory leak on radeon-kms (HD4250). The leak expands until all swap is filled and requires reboot. My simple observation is that it's mostly caused by a) web browsing and b) java-based apps.

@hps: Stupid question, what would your prefence be to monitor the "memory leaks per minute"? Is "vmstat -m" / min sufficient?

[hselasky]

Hi @Beeblebrox-BSD,

I think "dtrace" in FreeBSD would be excellent to figure this out. It can be used to show all unique backtraces of a function call over time. This way we should be able to narrow down pretty quickly who's responsible for the leaks.

Are you familiar with DTRACE ?

--HPS

[Beeblebrox-BSD]

Hello @hps,

Are you familiar with DTRACE ?

Unfortunately, no. I've loaded the DTRACE kernel module (ver bedc15ffb71(drm-next)-dirty) and did a syscall lookup which gave "# dtrace -n 'lockstat:::adaptive-block { @[execname] = sum(arg1)" seamonkey 33244 intr 42534 at-spi2-registryd 64533 usb 336355 cam 891244 pagedaemon 1378179 vmdaemon 5735154

• I only have 3 jails running & no other VM's, so the vmdaemon is referencing the linux layer I suppose.
• I would assume you would like to have a combination of Profiling, Raw Kernel & Syscalls (perhaps even more). Please tell me items you want from (or elsewhere) https://wiki.freebsd.org/DTrace/One-Liners

Regards.

[hselasky]

You'll need to load the dtraceall.ko for all symbols to show up.

[hselasky]

Can you re-test using the latest drm-next branch. Should be fixed now.

[jbeich]

I confirm, both /tmp/shmfd* and OpenGL leaks are gone. VAAPI still leaks: try starting mpv with --hwdec=vaapi for a short time in a loop. i915_gem_object and i915_gem_request (USED field) continuously grow and don't reset on killing Xserver.

[hselasky]

Some dtrace'ing reveals that the following path is leaking:

Ptr=0xfffff8022a622940 Size=24 Type=-2099233712
              i915kms.ko`alloc_pt+0x27
              i915kms.ko`gen8_alloc_va_range_3lvl+0x2b3
              i915kms.ko`gen8_alloc_va_range+0x444
              i915kms.ko`i915_vma_bind+0x65
              i915kms.ko`__i915_vma_do_pin+0x54c
              i915kms.ko`i915_gem_execbuffer_reserve_vma+0x128
              i915kms.ko`i915_gem_execbuffer_reserve+0x44f
              i915kms.ko`i915_gem_do_execbuffer+0x909
              i915kms.ko`i915_gem_execbuffer2+0x16b
              drm.ko`drm_ioctl+0x325
              linuxkpi.ko`linux_dev_ioctl+0xde
              kernel`devfs_ioctl+0xc3
              kernel`VOP_IOCTL_APV+0xe0
              kernel`vn_ioctl+0x10c
              kernel`devfs_ioctl_f+0x1f
              kernel`kern_ioctl+0x246
              kernel`sys_ioctl+0x171
              kernel`amd64_syscall+0x325
              kernel`0xffffffff80ecf84b

@markj : Any comments ?

[markjdb]

@hselasky that corresponds to a resource associated with GEM objects, so that's not very surprising given @jbeich's claim that the i915_gem_object count is continuously increasing. We need to figure out why GEM objects are not being released. Is this another refcounting problem?

[markjdb]

@jbeich where are you getting the GEM object count from? debugfs?

[jbeich]

vmstat -z or do you mean something else?

[markjdb]

I meant lindebugfs, but "vmstat -z" answers my question.

[hselasky]

Do we have any local patches in the code paths involved?

[mjoras]

I did a tiny bit of digging here. @hselasky , how did you determine that that was the path leaking, out of curiosity? Here's what I got from dtrace, just tracking some of the relevant functions (I had to force noinline two of them). I was running mpv --hwdec=vaapi jellyfish-3-mbps-hd-h264.mkv in between (which segfaults, so I'm not sure if it's entirely the same test):

[root@anomander] ~# dtrace -s gem.d
dtrace: script 'gem.d' matched 4 probes
^C

  i915_gem_execbuffer_reserve_vma                                   1
  i915_gem_execbuffer_unreserve_vma                                 1
  free_pt                                                           5
  alloc_pt                                                          7
[root@anomander] ~# dtrace -s gem.d
dtrace: script 'gem.d' matched 4 probes
^C

  i915_gem_execbuffer_reserve_vma                                   1
  i915_gem_execbuffer_unreserve_vma                                 1
  alloc_pt                                                          7
  free_pt                                                           7
[root@anomander] ~# dtrace -s gem.d
dtrace: script 'gem.d' matched 4 probes
^C

  i915_gem_execbuffer_reserve_vma                                   1
  i915_gem_execbuffer_unreserve_vma                                 1
  alloc_pt                                                          7
  free_pt                                                           7

So the first call allocates two extra pt's, but that doesn't account for the discrepancy in vmstat. I've just started looking at the code so I'll update if I find anything else.

[hselasky]

@mjoras : I've sent you my scripts off-list.

You need to install libva-intel-driver-1.8.2 for reproduction.

I'm using 12-current kernel and 11-stable userland.

[mjoras]

I have a bit more debugging output to report, using the following dtrace script:

fbt::drm_gem_object_unreference_unlocked:entry
{
    @num[arg0,probefunc] = count();
}
fbt::drm_gem_object_unreference:entry
{
    @num[arg0,probefunc] = count();
}
fbt::drm_gem_object_reference:entry
{
    @num[arg0,probefunc] = count();
}
fbt::i915_gem_free_object:entry
{
    @num[arg0,probefunc] = count();
}
fbt::i915_gem_object_create:return
{
    @num[arg1,probefunc] = count();

So what I'm trying to do is track the gem objects created by i915, identifying them by their addresses. I ran this three times after a fresh boot while doing the above mentioned repro where mpv crashes. I filtered it, and noted some interesting things. !!! indicates an allocation that didn't have a corresponding free, and ??? indicates a free without a corresponding allocation in that run. I also note the two times where an object was allocated in one iteration and freed in the next. Note that these weren't the only allocations, these were simply the ones that seemed like likely leak suspects.

   !!!
   -8788891407872  drm_gem_object_reference                                          5
   -8788891407872  drm_gem_object_unreference                                        1
   -8788891407872  drm_gem_object_unreference_unlocked                               5
   -8788891407872  i915_gem_object_create                                            1

   !!!
   -8788891408512  drm_gem_object_reference                                          6
   -8788891408512  drm_gem_object_unreference                                        1
   -8788891408512  drm_gem_object_unreference_unlocked                               6
   -8788891408512  i915_gem_free_object                                              1
   -8788891408512  i915_gem_object_create                                            2

   !!! <freed in next iteration>
   -8788891409152  i915_gem_object_create                                            1

   !!!
   -8795674953216  drm_gem_object_reference                                         11
   -8795674953216  drm_gem_object_unreference                                        6
   -8795674953216  drm_gem_object_unreference_unlocked                               5
   -8795674953216  i915_gem_object_create                                            1

   ???
   -8788891409152  drm_gem_object_unreference                                        1
   -8788891409152  i915_gem_free_object                                              1

   ???
   -8788891409792  drm_gem_object_unreference                                        1
   -8788891409792  i915_gem_free_object                                              1

   !!!
   -8788892136960  drm_gem_object_reference                                          5
   -8788892136960  drm_gem_object_unreference                                        1
   -8788892136960  drm_gem_object_unreference_unlocked                               5
   -8788892136960  i915_gem_object_create                                            1

   !!!
   -8788892137600  drm_gem_object_reference                                          6
   -8788892137600  drm_gem_object_unreference                                        1
   -8788892137600  drm_gem_object_unreference_unlocked                               6
   -8788892137600  i915_gem_free_object                                              1
   -8788892137600  i915_gem_object_create                                            2

   !!! <freed in next iteration>
   -8788892138240  i915_gem_object_create                                            1

   !!!
   -8788892179200  drm_gem_object_reference                                         11
   -8788892179200  drm_gem_object_unreference                                        6
   -8788892179200  drm_gem_object_unreference_unlocked                               5
   -8788892179200  i915_gem_object_create                                            1

   ???
   -8788892138240  drm_gem_object_unreference                                        1
   -8788892138240  i915_gem_free_object                                              1

   ???
   -8788892138880  drm_gem_object_unreference                                        1
   -8788892138880  i915_gem_free_object                                              1

   !!!
   -8794749111040  drm_gem_object_reference                                          4
   -8794749111040  drm_gem_object_unreference_unlocked                               4
   -8794749111040  i915_gem_object_create                                            1

   !!!
   -8794749113216  drm_gem_object_reference                                         11
   -8794749113216  drm_gem_object_unreference                                        6
   -8794749113216  drm_gem_object_unreference_unlocked                               5
   -8794749113216  i915_gem_object_create                                            1

   !!!
   -8795674957952  drm_gem_object_reference                                          5
   -8795674957952  drm_gem_object_unreference                                        1
   -8795674957952  drm_gem_object_unreference_unlocked                               5
   -8795674957952  i915_gem_object_create                                            1

   !!!
   -8795674959232  i915_gem_object_create                                            1

vmstat -z indicated that 11 more i915_gem_objects were used after running this than after startup.

There are a couple things I don't understand.

Why are we seeing frees for allocations we've never seen? I ran the script for 20 seconds after mpv exited, so you'd think we would be catching the object creation. As far as I can tell these gem objects aren't allocated when I'm sitting on the machine idle.

I don't totally understand the reference counting semantics being used here, but it seems like some of these should in fact be resulting in calls to i915_gem_object_free. Consider the first instance where there is one call to i915_gem_object_create, which creates the first reference, 5 subsequent calls to drm_gem_object_reference bring us to 6 references, and 6 calls to either drm_gem_object_unreference or drm_gem_object_unreference_unlocked, the last of which should, via kref_put_mutex, trigger the call to i915_gem_object_free.

So is there something wrong with kref_put_mutex?

[hselasky]

dtrace might have internal buffer overflows, leading to lost events.

BTW: Please also using dtrace to dump the reference count of the kref. Maybe that will reveal something!

[mjoras]

@hselasky, good suggestion. Here's an example that I think shows a definite inconsistency. What I am doing here is simply printing the reference count on entry, in addition to the walltimestamp to give a rough guess for overall ordering. This is all for one object, I edited out the address and other stuff for readability. Note this in object for which we never call i915_gem_free_object.

reference:entry                        1497824522870314462     1
reference:entry                        1497824522870314462     1
reference:entry                        1497824522870314462     2
reference:entry                        1497824522870314462     2
unreference_unlocked:entry             1497824522870314462     2
unreference_unlocked:entry             1497824522870314462     2
unreference_unlocked:entry             1497824522870314462     3

It is hard to know what ordering is correct for the above trace, but we know the net result. At this point we have the initial reference from creation + 4 reference calls and 3 unreference calls, which should leave 2 references... But that's not what happens. The following is what happens after in the trace, and I believe this is also the correct ordering that would explain why the free was never called:

reference:entry                        1497824522872314476     3
unreference:entry                      1497824522872314476     4
unreference_unlocked:entry             1497824522872314476     3
unreference_unlocked:entry             1497824522872314476     2

So after that first batch we actually ended with 3 references, and thus we end up with +1 reference, -3 for a final reference count of 1 after the last unreference call, hence the object is never freed.

This would seem to indicate there is some problem with drm_gem_object_unreference_unlocked is a very simply function that either calls kref_put if the drm object has gem_free_object_unlocked defined, else it calls kref_put_mutex. kref_put_mutex then is responsible for decrementing the refcount and, if it reaches 0, calling the release function (i915_gem_free_object).

So, I ask again, does this mean kref_put_mutex is broken? The implementation of it seems to have been copied directly from Linux pre-4.0 (more recent versions have been simplified to use a refcount_t API): http://elixir.free-electrons.com/linux/v3.19.8/source/include/linux/kref.h#L134

This is not a terribly complicated function, but it relies on two pieces working properly. mutex_lock does not seem likely to be broken, it is a direct wrapper around sx_xlock. What about atomic_add_unless and atomic_dec_and_test?

The former appears to be similar, but not totally the same as the pre-4 Linux version. Compare Linux vs linuxkpi:

static inline int __atomic_add_unless(atomic_t *v, int a, int u)
{
    int c, old;
    c = atomic_read(v);
    for (;;) {
        if (unlikely(c == (u)))
            break;
        old = atomic_cmpxchg((v), c, c + (a));
        if (likely(old == c))
            break;
        c = old;
    }
    return c;
}

atomic_add_unless(atomic_t *v, int a, int u)
{
        int c;

        for (;;) {
                c = atomic_read(v);
                if (unlikely(c == u))
                        break;
                if (likely(atomic_cmpset_int(&v->counter, c, c + a)))
                        break;
        }
        return (c != u);
}

I'm not an expert in atomic semantics, but these seem equivalent to me, and @hselasky actually modified it fairly recently in commit 6bd95caf293c. atomic_dec_and_test is similarly boring, wrapping atomic_fetchadd_int in what seems to be a correct way.

[hselasky]

@mjoras : You forgot this piece:

static inline int atomic_add_unless(atomic_t *v, int a, int u)
{
        return __atomic_add_unless(v, a, u) != u;
}

[mjoras]

Perhaps I'm barking up the wrong tree here. I replaced the implementation of kref_put_mutex with a completely separate one that only depends on atomic(9) functions, and yet I still see the problem:

static inline int kref_put_mutex(struct kref *kref,
    void (*release)(struct kref *kref), struct mutex *lock)
{
        int old, new;
        do {
                old = atomic_load_acq_int(&kref->refcount.counter);
                if (old == 1) {
                        mutex_lock(lock);
                        if ((atomic_fetchadd_int(&kref->refcount.counter, -1) - 1) == 0) {
                                release(kref);
                                return 1;
                        }
                        mutex_unlock(lock);
                        return 0;
                }
                new = (old - 1);
        } while (!atomic_cmpset_int(&kref->refcount.counter, old, new));

        return 0;
}

[hselasky]

@mjoras : From what I can see the kref() functions are done properly. Some investigation today lead me to looking at non-paired use of intel_lr_context_pin() and intel_lr_context_unpin().

Try this patch for the code:

diff --git a/drivers/gpu/drm/i915/intel_lrc.c b/drivers/gpu/drm/i915/intel_lrc.c
index bef72fb1775..d9e382a8c85 100644
--- a/drivers/gpu/drm/i915/intel_lrc.c
+++ b/drivers/gpu/drm/i915/intel_lrc.c
@@ -230,7 +230,7 @@ enum {

 static int execlists_context_deferred_alloc(struct i915_gem_context *ctx,
                                            struct intel_engine_cs *engine);
-static int intel_lr_context_pin(struct i915_gem_context *ctx,
+int intel_lr_context_pin(struct i915_gem_context *ctx,
                                struct intel_engine_cs *engine);
 static void execlists_init_reg_state(u32 *reg_state,
                                     struct i915_gem_context *ctx,
@@ -712,7 +712,7 @@ intel_logical_ring_advance(struct drm_i915_gem_request *request)
        return 0;
 }

-static int intel_lr_context_pin(struct i915_gem_context *ctx,
+int intel_lr_context_pin(struct i915_gem_context *ctx,
                                struct intel_engine_cs *engine)
 {
        struct intel_context *ce = &ctx->engine[engine->id];

Then run this dtrace script:

#!/usr/sbin/dtrace -s

fbt::intel_lr_context_pin:entry
{
        @[probefunc, arg0, arg1] = count();
    printf("%d %d\n", arg0, arg1);
    stack();
}

fbt::intel_lr_context_unpin:entry
{
        @[probefunc, arg0, arg1] = count();
    printf("%d %d\n", arg0, arg1);
    stack();
}

Another idea: Put all GEM objects on a linked list when you allocate them, and remove them from this linked list when you free them. Then every second or whatever iterate the list passing core refcounts as arguments to a global function which you can in turn dtrace.

[hselasky]

Hi @mjoras , I have found a fix for the VAAPI memleak issue! Will commit it shortly to drm-next. It is due to 2 small bugs in the dma-buf API in the LinuxKPI :-) --HPS

[mjoras]

@hselasky Awesome! :)

[hselasky]

@mjoras : You'll be surprised when you see the patch :-)

[hselasky]

Please re-open this issue if more memory leaks are found. Or create a new one. Thank you!

[jbeich]

I confirm, both /tmp/shmfd* and OpenGL leaks are gone.

/tmp/shmfd* was a false positive as DRI3 is currently disabled by default. Fixed by freebsd/freebsd-ports@1acb9b61f4c9.