Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Memory issue with the imagick initialization #72

Closed
palaiya opened this issue Mar 3, 2016 · 20 comments
Closed

Memory issue with the imagick initialization #72

palaiya opened this issue Mar 3, 2016 · 20 comments

Comments

@palaiya
Copy link

palaiya commented Mar 3, 2016

I have explained the code in the following link. Which uses the

    imagick.Initialize() 
    defer imagick.Terminate() 

to initialize the library. If, I don't include these lines in the code my /tmp folder size keep on increasing. Where as on the other hand if i include them in code my RAM size increases monotonously and in the end my handler crashes. Kindly look into this matter. Why is it happening. Moreover, as such i don't have any memory leak in my code.

func CreateMaster(keyName string, desiredAspectRatio float64, isMaster bool) bool {             

    s3Client := s3.New(session.New(), &aws.Config{Region: aws.String(region)})
        params := &s3.GetObjectInput{
        Bucket: aws.String(bucketName),
        Key: aws.String(keyName),
        }

    fmt.Println(" Master creation request for key : " + keyName)
    out, err := s3Client.GetObject(params)

    if err != nil { 
        return false                                       
    }

    defer out.Body.Close()  
    img, err := ioutil.ReadAll(out.Body)

    if err != nil { 
            return false      
    }                   

    mw := imagick.NewMagickWand()
    defer mw.Destroy()

    err = mw.ReadImageBlob(img)
    if err != nil {  
        return false                   
    }


    if isMaster == false {
        paramsPut := &s3.PutObjectInput{
                    Bucket:         aws.String(masterBucketName),
                    Key:            aws.String(keyName),
                    Body:         bytes.NewReader(mw.GetImageBlob()),
            }

        _, err = s3Client.PutObject(paramsPut)
        if err != nil {
            log.Printf("Couldn't put the image on s3 : " + keyName + "%s\n", err)       
        }

        return true
    }


        originalWidth := float64(mw.GetImageWidth())
        originalHeight := float64(mw.GetImageHeight())

    imageAspectRatio  := originalWidth / originalHeight
        masterWidth := cwMasterWidth
        masterHeight := cwMasterHeight
        masterAspectRatio := math.Trunc((cwMasterWidth / cwMasterHeight) * 100)/100

    if masterAspectRatio != desiredAspectRatio {           
                    masterAspectRatio = desiredAspectRatio
                }


    pwm := imagick.NewPixelWand()
    defer pwm.Destroy()

    tx := imagick.NewMagickWand()
    defer tx.Destroy()  

    if isMaster == true {               

            var w, h uint = 0, 0
            size := fmt.Sprintf("%dx%d^+0+0", w, h) 
                    if imageAspectRatio <= masterAspectRatio {                
                        // trim the height
            w = uint(originalWidth)
            h = (uint(originalWidth / masterAspectRatio))
               size = fmt.Sprintf("%dx%d^+0+0", w, h)
                     } else { 
                        // trim the width
            w = uint(originalHeight * masterAspectRatio)
            h = uint(originalHeight)
            size = fmt.Sprintf("%dx%d^+0+0", w, h)
                     }

            tx = mw.TransformImage("", size)        
            tx.SetImageGravity(imagick.GRAVITY_CENTER)
            offsetX := -(int(w) - int(tx.GetImageWidth())) / 2
            offsetY := -(int(h) - int(tx.GetImageHeight())) / 2
            err := tx.ExtentImage(w, h, offsetX, offsetY)

                    if float64(tx.GetImageWidth()) > masterWidth && float64(tx.GetImageHeight()) > masterHeight  {                                        
                        err = tx.ResizeImage(uint(masterWidth), uint(masterHeight), imagick.FILTER_BOX, 1)
            if err != nil {
                log.Printf("Inside CreateMaster function Couldn't resize the image : " + keyName + "%s\n", err) 
                return false                 
            }                                                           
                    }                                       
                }       

     paramsPut := &s3.PutObjectInput{
                    Bucket:         aws.String(masterBucketName),
                    Key:            aws.String(keyName),
                    Body:         bytes.NewReader(tx.GetImageBlob()),
            }

    _, err = s3Client.PutObject(paramsPut)
    if err != nil {
        log.Printf("Inside CreateMaster function Couldn't put the image on s3 : " + keyName + "%s\n", err)  
        return false        
    }

    return true
}

http://stackoverflow.com/questions/35768266/memory-leak-in-go-lang-http-handler

@justinfx
Copy link
Member

justinfx commented Mar 3, 2016

The call to Initialize and Terminate need to happen, so lets put that aside.

Would you be able to reduce your code into a smaller example that would enable us to easily reproduce the memory leak?

@xealot
Copy link
Contributor

xealot commented Mar 3, 2016

I use these bindings as part of a web application, I don't believe I call Initialize/Terminate.

The process runs forever, when would be the appropriate time to call these functions?

@palaiya
Copy link
Author

palaiya commented Mar 4, 2016

@justinfx If let' s say what your are saying is correct then memory leak should be in CreateMaster function. So, i have pasted the code here. For more information you can refer to the SO link.

@justinfx
Copy link
Member

justinfx commented Mar 4, 2016

@xealot , ideally you would call them in your main(). I'm only saying we should assume they should be called because ImageMagick says they should. And iMagick is simply a binding.

@justinfx
Copy link
Member

justinfx commented Mar 4, 2016

@palaiyacw I appreciate the paste. However a runnable repro would have been better. But I can just try to repro the iMagick operations you are doing here and see if I can find a leak. Since iMagick is a thin binding, technically I should only have to look as far as the iMagick methods that you call to see if we overlooked releasing temp resources while calling into C.

@palaiya
Copy link
Author

palaiya commented Mar 4, 2016

@justinfx I would appreciate that. If you can see whether temp resources are being release or not in the iMagick method and please reproduce the operation according to your suitability

@justinfx
Copy link
Member

justinfx commented Mar 6, 2016

I took a look and didn't see anything stand out in the Imagick layer that would cause the leak. The wrapper functions are very very small, and I see cleanups for any allocated C memory. I tried to reproduce it using your example, and all the http and S3 stuff removed. Didn't see a leak. Can you take this code and try to make it leak?

package main

import (
    "fmt"
    "io/ioutil"
    "log"
    "os"
    "runtime"

    "gopkg.in/gographics/imagick.v2/imagick"
)

const SrcImage = `/path/to/source/image.jpg`

func main() {

    imagick.Initialize()
    defer imagick.Terminate()

    i := 0
    var stats runtime.MemStats

    for {

        Process()

        runtime.ReadMemStats(&stats)

        i++
        fmt.Printf("After run #%04d: Alloc: %v, Idle: %v, InUse: %v, Objects: %v\n", i,
            stats.HeapAlloc, stats.HeapIdle, stats.HeapInuse, stats.HeapObjects)
    }
}

func Process() {

    f, err := os.Open(SrcImage)
    if err != nil {
        log.Fatalf("Failed to open source image: %v", err)
    }
    defer f.Close()

    img, err := ioutil.ReadAll(f)
    if err != nil {
        log.Fatalf("Failed to read image file: %v", err)
    }

    mw := imagick.NewMagickWand()
    defer mw.Destroy()

    err = mw.ReadImageBlob(img)
    if err != nil {
        log.Fatalf("Failed to read image blob: %v", err)
    }

    originalWidth := float64(mw.GetImageWidth())
    originalHeight := float64(mw.GetImageHeight())

    imageAspectRatio := originalWidth / originalHeight

    masterWidth := 320.0
    masterHeight := 180.0
    masterAspectRatio := masterWidth / masterHeight

    pwm := imagick.NewPixelWand()
    defer pwm.Destroy()

    tx := imagick.NewMagickWand()
    defer tx.Destroy()

    var w, h uint = 0, 0
    size := fmt.Sprintf("%dx%d^+0+0", w, h)
    if imageAspectRatio <= masterAspectRatio {
        // trim the height
        w = uint(originalWidth)
        h = (uint(originalWidth / masterAspectRatio))
        size = fmt.Sprintf("%dx%d^+0+0", w, h)
    } else {
        // trim the width
        w = uint(originalHeight * masterAspectRatio)
        h = uint(originalHeight)
        size = fmt.Sprintf("%dx%d^+0+0", w, h)
    }

    tx = mw.TransformImage("", size)
    tx.SetImageGravity(imagick.GRAVITY_CENTER)
    offsetX := -(int(w) - int(tx.GetImageWidth())) / 2
    offsetY := -(int(h) - int(tx.GetImageHeight())) / 2
    err = tx.ExtentImage(w, h, offsetX, offsetY)
    if err != nil {
        log.Fatalf("Failed calling ExtendImage(%v, %v, %v, %v): %v",
            w, h, offsetX, offsetY, err)
    }

    if float64(tx.GetImageWidth()) > masterWidth && float64(tx.GetImageHeight()) > masterHeight {

        err = tx.ResizeImage(uint(masterWidth), uint(masterHeight), imagick.FILTER_BOX, 1)
        if err != nil {
            log.Fatalf("Inside CreateMaster function Couldn't "+
                "resize the image %s: %s", SrcImage, err)
        }
    }

}

@palaiya
Copy link
Author

palaiya commented Mar 7, 2016

@justinfx Actually even i also find difficult to replicate the same issue while testing the code locally. I tested your code and couldn't find anything. But I am attaching the screen shot of my /tmp folder on production machine. In which a lot of magick-* object gets created and they persist there. Moreover, Memory footprint increase constantly and then handler get crashed.

I am attaching the syslog as well as screen shot of tmp folder :

Mar 6 15:57:24 kernel: [1678161.900511] Out of memory: Kill process 14505 (goImgProcess) score 917 or sacrifice child Mar 6 15:57:24 kernel: [1678161.906584] Killed process 14505 (goImgProcess) total-vm:9878228kB, anon-rss:7013676kB,

leak

Just one more point i want to raise here is that i keep all images in the memory and resize them in memory and write it to the client. So, could it be the related to GC.

@justinfx
Copy link
Member

justinfx commented Mar 7, 2016

The temp file stuff is going to be more related to ImageMagick directly, so you may want to follow up with the maintainers or the ImageMagick community. Out of curiosity, does the call to imagick.Terminate() cause the temp files to get cleaned up? If so, then I suspect there could be a general issue with long running processes and ImageMagick. If calling ImageMagick's terminate is the only way to get it to clean up its resources, then maybe a "terminate" followed by a "initialize", periodically, is the only work around. But that would be unsafe for concurrent use and would require a reader/writer lock so that many goroutines can use imagick, but once the terminate/initialize happens, it acquires a write lock and blocks the readers.

If we can't get a local reproduction working, then I am not too sure what to do from here. For all I know, ImageMagick is still hanging onto memory until Terminate is called.

I also had a long running Image Cache Server running with imagick. It would serve cached blobs out of an LRU, and when a request image doesn't exist, it would read it, transform it, and cache it. I don't recall running into this problem. But I have since migrated to using my other bindings, for OpenImageIO: https://github.com/justinfx/openimageigo

@justinfx
Copy link
Member

justinfx commented Mar 7, 2016

Here is another question... if you completely disable the S3 logic in your code, and always perform the image processing and serving, does it still have the memory issues? I want to remove the possibility of the leak happening somewhere in the S3 area.

@palaiya
Copy link
Author

palaiya commented Mar 7, 2016

@justinfx I have tested your code on amazon ec2 machine and I can see the memory footprint increasing constantly. Here are the screen shots of the same.

EC2 machine OS info:
Distributor ID: Ubuntu
Description: Ubuntu 14.04.3 LTS
Release: 14.04
Codename: trusty

1
2

@justinfx
Copy link
Member

justinfx commented Mar 7, 2016

If you run it with GODEBUG=gctrace=1, what kind of output are you seeing from the garbage collector? I don't get the leak on my local osx laptop. I'm testing under go.1.6

What version of ImageMagick is this? Which branch of imagick are you using?

@palaiya
Copy link
Author

palaiya commented Mar 7, 2016

I have tested with go version go1.5.3 linux/amd64, ImageMagick version ImageMagick 6.9.3-7 Q16 x86_64 2016-03-07 and imagick branch : im-6.8.9

Output of the program :
After run #1: Alloc: 2169520, Idle: 516096, InUse: 2367488, Objects: 199
After run #2: Alloc: 1112168, Idle: 3530752, InUse: 1351680, Objects: 168
After run #3: Alloc: 3207840, Idle: 1425408, InUse: 3457024, Objects: 201
After run #4: Alloc: 1636960, Idle: 4055040, InUse: 1875968, Objects: 173
After run #5: Alloc: 3732584, Idle: 1949696, InUse: 3981312, Objects: 205
After run #6: Alloc: 1899424, Idle: 4841472, InUse: 2138112, Objects: 179
After run #7: Alloc: 3995048, Idle: 2736128, InUse: 4243456, Objects: 211
After run #8: Alloc: 2030480, Idle: 4702208, InUse: 2277376, Objects: 180
After run #9: Alloc: 4126104, Idle: 2596864, InUse: 4382720, Objects: 212
After run #10: Alloc: 2096064, Idle: 4636672, InUse: 2342912, Objects: 182
After run #11: Alloc: 4191688, Idle: 2531328, InUse: 4448256, Objects: 214
After run #12: Alloc: 2153472, Idle: 4579328, InUse: 2400256, Objects: 186
After run #13: Alloc: 1113024, Idle: 5619712, InUse: 1359872, Objects: 178
After run #14: Alloc: 3208648, Idle: 3514368, InUse: 3465216, Objects: 210
After run #15: Alloc: 1637376, Idle: 5095424, InUse: 1884160, Objects: 180
After run #16: Alloc: 3733000, Idle: 2990080, InUse: 3989504, Objects: 212
After run #17: Alloc: 1637504, Idle: 5095424, InUse: 1884160, Objects: 182
After run #18: Alloc: 3733128, Idle: 2990080, InUse: 3989504, Objects: 214
After run #19: Alloc: 1899584, Idle: 4833280, InUse: 2146304, Objects: 182
After run #20: Alloc: 3995208, Idle: 2727936, InUse: 4251648, Objects: 214
After run #21: Alloc: 2030592, Idle: 4702208, InUse: 2277376, Objects: 182
After run #22: Alloc: 4126216, Idle: 2596864, InUse: 4382720, Objects: 214
After run #23: Alloc: 2096192, Idle: 4636672, InUse: 2342912, Objects: 184
After run #24: Alloc: 4191816, Idle: 2531328, InUse: 4448256, Objects: 216
After run #25: Alloc: 2153520, Idle: 4579328, InUse: 2400256, Objects: 187
After run #26: Alloc: 1113136, Idle: 5619712, InUse: 1359872, Objects: 180
After run #27: Alloc: 3208760, Idle: 3514368, InUse: 3465216, Objects: 212
After run #28: Alloc: 1637488, Idle: 5095424, InUse: 1884160, Objects: 182
After run #29: Alloc: 3733112, Idle: 2990080, InUse: 3989504, Objects: 214
After run #30: Alloc: 1899632, Idle: 4833280, InUse: 2146304, Objects: 183
After run #31: Alloc: 3995256, Idle: 2727936, InUse: 4251648, Objects: 215
After run #32: Alloc: 2030704, Idle: 4702208, InUse: 2277376, Objects: 184

@justinfx
Copy link
Member

justinfx commented Mar 7, 2016

What about the output with gotrace=1?
Set the env key

GODEBUG=gctrace=1

@palaiya
Copy link
Author

palaiya commented Mar 7, 2016

After run #1: Alloc: 2170240, Idle: 483328, InUse: 2367488, Objects: 196
gc 1 @0.319s 0%: 0.20+0.19+0.002+0.58+0.30 ms clock, 0.40+0.19+0+0/0.065/0.014+0.61 ms cpu, 4->4->1 MB, 4 MB goal, 4 P
After run #2: Alloc: 1111688, Idle: 3547136, InUse: 1335296, Objects: 162
After run #3: Alloc: 3207360, Idle: 1441792, InUse: 3440640, Objects: 195
gc 2 @0.943s 0%: 0.022+0.15+0.039+0.080+0.32 ms clock, 0.091+0.15+0+0.037/0.008/0.039+1.3 ms cpu, 4->5->1 MB, 4 MB goal, 4 P
After run #4: Alloc: 1636800, Idle: 4063232, InUse: 1867776, Objects: 172
After run #5: Alloc: 3732424, Idle: 1957888, InUse: 3973120, Objects: 204
gc 3 @1.570s 0%: 0.028+0.16+0.11+0.066+0.33 ms clock, 0.11+0.16+0+0.005/0.002/0.090+1.3 ms cpu, 4->5->1 MB, 4 MB goal, 4 P
After run #6: Alloc: 1898944, Idle: 4849664, InUse: 2129920, Objects: 173
After run #7: Alloc: 3994568, Idle: 2744320, InUse: 4235264, Objects: 205
gc 4 @2.195s 0%: 0.14+0.15+0.026+0.20+0.48 ms clock, 0.57+0.15+0+0/0.029/0.063+1.9 ms cpu, 4->5->1 MB, 5 MB goal, 4 P
After run #8: Alloc: 1898944, Idle: 4849664, InUse: 2129920, Objects: 173
After run #9: Alloc: 3994568, Idle: 2744320, InUse: 4235264, Objects: 205
gc 5 @2.820s 0%: 0.034+0.10+0.026+0.15+0.28 ms clock, 0.13+0.10+0+0/0.017/0.087+1.1 ms cpu, 4->4->0 MB, 5 MB goal, 4 P
After run #10: Alloc: 2029952, Idle: 4718592, InUse: 2260992, Objects: 173
After run #11: Alloc: 4125576, Idle: 2613248, InUse: 4366336, Objects: 205
gc 6 @3.443s 0%: 0.013+0.092+0.069+0.090+0.32 ms clock, 0.052+0.092+0+0/0.004/0.095+1.2 ms cpu, 4->4->0 MB, 5 MB goal, 4 P
After run #12: Alloc: 2095488, Idle: 4653056, InUse: 2326528, Objects: 174
After run #13: Alloc: 4191112, Idle: 2547712, InUse: 4431872, Objects: 206
gc 7 @4.068s 0%: 0.026+0.12+0.002+0.18+0.30 ms clock, 0.10+0.12+0+0.016/0.020/0.050+1.2 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
After run #14: Alloc: 2152880, Idle: 4587520, InUse: 2392064, Objects: 178
gc 8 @4.389s 0%: 0.035+0.12+0.002+0.10+0.31 ms clock, 0.14+0.12+0+0/0.029/0.062+1.2 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
After run #15: Alloc: 1112560, Idle: 5619712, InUse: 1359872, Objects: 172
After run #16: Alloc: 3208232, Idle: 3514368, InUse: 3465216, Objects: 205
gc 9 @5.014s 0%: 0.031+0.22+0.067+0.089+0.32 ms clock, 0.12+0.22+0+0.064/0.006/0.002+1.3 ms cpu, 4->5->1 MB, 4 MB goal, 4 P
After run #17: Alloc: 1636960, Idle: 5095424, InUse: 1884160, Objects: 175
After run #18: Alloc: 3732584, Idle: 2990080, InUse: 3989504, Objects: 207
gc 10 @5.640s 0%: 0.018+0.16+0.024+0.17+0.28 ms clock, 0.072+0.16+0+0/0.003/0.11+1.1 ms cpu, 4->5->1 MB, 4 MB goal, 4 P
After run #19: Alloc: 1899104, Idle: 4833280, InUse: 2146304, Objects: 176
After run #20: Alloc: 3994728, Idle: 2727936, InUse: 4251648, Objects: 208
gc 11 @6.268s 0%: 0.018+0.10+0.050+0.082+0.31 ms clock, 0.073+0.10+0+0/0.008/0.087+1.2 ms cpu, 4->4->0 MB, 5 MB goal, 4 P
After run #21: Alloc: 2030112, Idle: 4702208, InUse: 2277376, Objects: 176
After run #22: Alloc: 4125736, Idle: 2596864, InUse: 4382720, Objects: 208
gc 12 @6.892s 0%: 0.040+0.18+0.074+0.25+0.30 ms clock, 0.16+0.18+0+0.034/0.23/0.050+1.2 ms cpu, 4->5->1 MB, 5 MB goal, 4 P
After run #23: Alloc: 2095648, Idle: 4636672, InUse: 2342912, Objects: 177
After run #24: Alloc: 4191272, Idle: 2531328, InUse: 4448256, Objects: 209
gc 13 @7.519s 0%: 0.034+0.12+0.029+0.18+0.30 ms clock, 0.13+0.12+0+0.006/0.021/0.077+1.2 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
After run #25: Alloc: 2153040, Idle: 4579328, InUse: 2400256, Objects: 181
gc 14 @7.832s 0%: 0.027+0.11+0.002+0.12+0.29 ms clock, 0.11+0.11+0+0/0.039/0.061+1.1 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
After run #26: Alloc: 1112720, Idle: 5619712, InUse: 1359872, Objects: 175
After run #27: Alloc: 3208344, Idle: 3514368, InUse: 3465216, Objects: 207
gc 15 @8.455s 0%: 0.032+0.25+0.036+0.067+0.31 ms clock, 0.13+0.25+0+0.037/0.001/0.034+1.2 ms cpu, 4->5->1 MB, 4 MB goal, 4 P
After run #28: Alloc: 1637072, Idle: 5095424, InUse: 1884160, Objects: 177
After run #29: Alloc: 3732696, Idle: 2990080, InUse: 3989504, Objects: 209
gc 16 @9.085s 0%: 0.028+0.15+0.020+0.19+0.27 ms clock, 0.11+0.15+0+0.008/0.002/0.093+1.0 ms cpu, 4->5->1 MB, 4 MB goal, 4 P
After run #30: Alloc: 1899216, Idle: 4833280, InUse: 2146304, Objects: 178
After run #31: Alloc: 3994840, Idle: 2727936, InUse: 4251648, Objects: 210
gc 17 @9.712s 0%: 0.028+0.12+0.074+0.098+0.49 ms clock, 0.11+0.12+0+0.006/0.024/0.065+1.9 ms cpu, 4->5->1 MB, 5 MB goal, 4 P
After run #32: Alloc: 2030272, Idle: 4702208, InUse: 2277376, Objects: 179
After run #33: Alloc: 4125896, Idle: 2596864, InUse: 4382720, Objects: 211
gc 18 @10.342s 0%: 0.040+0.10+0.030+0.13+0.31 ms clock, 0.12+0.10+0+0.009/0.002/0.087+0.95 ms cpu, 4->4->0 MB, 5 MB goal, 4 P
After run #34: Alloc: 2030320, Idle: 4702208, InUse: 2277376, Objects: 180
After run #35: Alloc: 4125944, Idle: 2596864, InUse: 4382720, Objects: 212
gc 19 @10.964s 0%: 0.036+0.15+0.002+0.11+0.30 ms clock, 0.14+0.15+0+0/0.001/0.10+1.2 ms cpu, 4->4->0 MB, 5 MB goal, 4 P
After run #36: Alloc: 2095856, Idle: 4636672, InUse: 2342912, Objects: 181
After run #37: Alloc: 4191480, Idle: 2531328, InUse: 4448256, Objects: 213
gc 20 @11.588s 0%: 0.034+0.12+0.002+0.17+0.31 ms clock, 0.13+0.12+0+0/0.031/0.067+1.2 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
After run #38: Alloc: 2153248, Idle: 4579328, InUse: 2400256, Objects: 185
gc 21 @11.903s 0%: 0.028+0.11+0.002+0.27+0.33 ms clock, 0.11+0.11+0+0/0.027/0.068+1.3 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
After run #39: Alloc: 1112928, Idle: 5619712, InUse: 1359872, Objects: 179
After run #40: Alloc: 3208552, Idle: 3514368, InUse: 3465216, Objects: 211
gc 22 @12.528s 0%: 0.024+0.093+0.14+0.074+0.32 ms clock, 0.099+0.093+0+0/0.002/0.094+1.3 ms cpu, 4->5->1 MB, 4 MB goal, 4 P
After run #41: Alloc: 1637280, Idle: 5095424, InUse: 1884160, Objects: 181
After run #42: Alloc: 3732904, Idle: 2990080, InUse: 3989504, Objects: 213
gc 23 @13.152s 0%: 0.027+0.14+0.028+0.19+0.28 ms clock, 0.11+0.14+0+0.008/0.011/0.11+1.1 ms cpu, 4->5->1 MB, 4 MB goal, 4 P
After run #43: Alloc: 1899424, Idle: 4833280, InUse: 2146304, Objects: 182
After run #44: Alloc: 3995048, Idle: 2727936, InUse: 4251648, Objects: 214
gc 24 @13.774s 0%: 0.014+0.11+0.043+0.088+0.30 ms clock, 0.057+0.11+0+0/0.006/0.094+1.2 ms cpu, 4->4->0 MB, 5 MB goal, 4 P
After run #45: Alloc: 2030480, Idle: 4702208, InUse: 2277376, Objects: 183
After run #46: Alloc: 4126104, Idle: 2596864, InUse: 4382720, Objects: 215
gc 25 @14.397s 0%: 0.039+0.10+0.042+0.10+0.31 ms clock, 0.15+0.10+0+0/0.001/0.094+1.2 ms cpu, 4->4->0 MB, 5 MB goal, 4 P
After run #47: Alloc: 2096016, Idle: 4636672, InUse: 2342912, Objects: 184
After run #48: Alloc: 4191640, Idle: 2531328, InUse: 4448256, Objects: 216
gc 26 @15.024s 0%: 0.018+0.11+0.041+0.14+0.27 ms clock, 0.073+0.11+0+0.012/0.005/0.083+1.0 ms cpu, 4->4->1 MB, 4 MB goal, 4 P
After run #49: Alloc: 2153424, Idle: 4579328, InUse: 2400256, Objects: 188
gc 27 @15.338s 0%: 0.025+0.097+0.047+0.085+0.32 ms clock, 0.10+0.097+0+0/0.009/0.082+1.2 ms cpu, 4->4->1 MB, 5 MB goal, 4 P
After run #50: Alloc: 1113232, Idle: 5619712, InUse: 1359872, Objects: 184
After run #51: Alloc: 3208856, Idle: 3514368, InUse: 3465216, Objects: 216
gc 28 @15.960s 0%: 0.008+0.10+0.14+0.071+0.30 ms clock, 0.035+0.10+0+0/0.003/0.088+1.2 ms cpu, 4->5->1 MB, 4 MB goal, 4 P

@palaiya
Copy link
Author

palaiya commented Mar 7, 2016

@justinfx You need to make it run for atleast 1000 run. You will then notice memory footprint increase gradually.

@justinfx
Copy link
Member

justinfx commented Mar 7, 2016

I've found the issue. You have a bug in your code and you are leaking a wand:

Here, you allocate a new wand and defer it to destroy:

tx := imagick.NewMagickWand()
    defer tx.Destroy()  

But then further down, you replace it with the wand that is returned from the call to TransformImage():

            tx = mw.TransformImage("", size)        
            tx.SetImageGravity(imagick.GRAVITY_CENTER)

If you completely get rid of the first allocation of that new magick wand, and simply make sure to Destroy() that new wand returned from TransformImage(), the leak goes away.

This happens because the current design of imagick is for the user to make sure they free all of their resources explicitly, just like files and sockets. There is a pending pull request, #62, which adds a finalizer to objects, so that they will always get destroyed once they are garbage collected.

Can you test and confirm?

@palaiya
Copy link
Author

palaiya commented Mar 8, 2016

@justinfx Thanking you so much. It finally fixed the leak from my code. But i couldn't understand i am just assigning a new value in the txobject. So, why didn't it destroy the earlier reference. Also, how did you debug this. So, that in future i can also do it on my own.

@justinfx
Copy link
Member

justinfx commented Mar 8, 2016

The arguments to the defer statement are evaluated when the defer executes. Not when the function is evaluated. You were scheduling the original object to destroy and not the new one. Either way, regardless of whether it applies when the defer evaluates or later, you leak an object. It just happens, because of the language spec, that you leak the larger one (the later one that sucks up the memory)

@justinfx justinfx closed this as completed Mar 8, 2016
@justinfx
Copy link
Member

justinfx commented Mar 8, 2016

Also my method of debuging was to comment out most the code and test, then observe the results and slowly uncomment more code until I could pinpoint when a leak was observable. It wasn't until I introduced the tx logic that I saw the leak. And when I stared more closely at it, I ended up seeing the reassignment

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants