fatal error: unexpected signal during runtime execution about imagick

[justinfx]

Can you show an example of your code and how you are using imagick?

I have used imagick within an http service and performed many resizes, quickly. Are you trying to share an instance of a MagickWand across goroutines? Are you trying to initialize and terminate the Imagick environment from multiple goroutines.

Make sure you create and destroy unique MagickWand instanced in each http request

[Ivanezko]

http.HandleFunc("/crop", cropper.CropImage)
http.ListenAndServe(server, nil)
package cropper

import (
"github.com/gographics/imagick/imagick"
"log"
"net/http"
"strconv"
"fmt"
"time"
)

func init() {

}

// Resize image
func CropImage(w http.ResponseWriter, r *http.Request) {
....

imagick.Initialize()
defer imagick.Terminate()

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

start := time.Now()
err = mw.ReadImage(fileName)
if err != nil {
panic(err)
}
log.Printf("Loading image took %v\n", time.Now().Sub(start))
start = time.Now()
err = mw.CropImage(uint(source_width), uint(source_height), int(source_x), int(source_y))
if err != nil {
panic(err)
}
log.Printf("Cropping image took %v\n", time.Now().Sub(start))
start = time.Now()
err = mw.ResizeImage(uint(width), uint(height), imagick.FILTER_LANCZOS, 1)
if err != nil {
panic(err)
}
log.Printf("Resizing image took %v\n", time.Now().Sub(start))
start = time.Now()
err = mw.SetImageCompressionQuality(95)
if err != nil {
panic(err)
}

err = mw.SetImageFormat("JPEG")
if err != nil {
panic(err)
}

blob := mw.GetImageBlob()

w.Header().Set("Content-type", "image/jpeg")
w.Header().Set("X-Accel-Expires", "604800")

fmt.Fprintf(w, "%s", blob)

log.Printf("Printing image took %v\n", time.Now().Sub(start))

}

9 дек. 2015 г., в 20:21, Justin Israel [email protected] написал(а):

Can you show an example of your code and how you are using imagick?

I have used imagick within an http service and performed many resizes, quickly. Are you trying to share an instance of a MagickWand across goroutines? Are you trying to initialize and terminate the Imagick environment from multiple goroutines.

Make sure you create and destroy unique MagickWand instanced in each http request

—
Reply to this email directly or view it on GitHub #64 (comment).

[justinfx]

func CropImage(w http.ResponseWriter, r *http.Request) {
...
   imagick.Initialize()
   defer imagick.Terminate()

Don't do that. You are supposed to do it once for the entire application. You are tearing down the entire ImageMagick system after each request :-)

You can move this to your application main(), or an init function. If you put it in an init() function, you should only need the initialize() call. A webserver probably doesnt need to call terminate()

[Ivanezko]

thank you very much!
you saved my day

9 дек. 2015 г., в 23:28, Justin Israel [email protected] написал(а):

func CropImage(w http.ResponseWriter, r *http.Request) {
...
imagick.Initialize()
defer imagick.Terminate()
Don't do that. You are supposed to do it once for the entire application. You are tearing down the entire ImageMagick system after each request :-)

You can move this to your application main(), or an init function. If you put it in an init() function, you should only need the initialize() call. A webserver probably doesnt need to call terminate()

—
Reply to this email directly or view it on GitHub #64 (comment).

[justinfx]

No problem!

[fvm]

I'm experiencing this exact same issue. Moreover, I've verified that I only initialise imagick just once, in the init, so that doesn't appear to be the cause.

Below you can find the (start of) stacktrace of one of the panics, specifically, the part which I keep seeing with every panic, i.e. from "ReadImage` onwards.

As with the original case, this doesn't occur upon processing occasional individual images, but when we start processing images quickly it does.

[signal 0xb code=0x1 addr=0x40 pc=0x7f35815e4890]
runtime stack:
runtime.throw(0xac3660, 0x2a)
/usr/local/go/src/runtime/panic.go:547 +0x90
runtime.sigpanic()
/usr/local/go/src/runtime/sigpanic_unix.go:12 +0x5a
goroutine 9229 [syscall, locked to thread]:
runtime.cgocall(0x8429e0, 0xc82013cda0, 0xc800000000)
/usr/local/go/src/runtime/cgocall.go:123 +0x11b fp=0xc82013cd50 sp=0xc82013cd20
stash.tools.bol.com/mir/escher/vendor/gopkg.in/gographics/imagick.v2/imagick._Cfunc_MagickReadImageBlob(0x7f35980012a0, 0xc820754000, 0x1f4646, 0x0)
??:0 +0x41 fp=0xc82013cda0 sp=0xc82013cd50
stash.tools.bol.com/mir/escher/vendor/gopkg.in/gographics/imagick.v2/imagick.(*MagickWand).ReadImageBlob(0xc820222660, 0xc820754000, 0x1f4646, 0x1f4646, 0x0, 0x0)

Now, one of the things I do is use a Sync.Pool, like below. Perhaps these somehow conflict?

var wandPool = sync.Pool{
    New: func() interface{} {
        m := imagick.NewMagickWand()
        return m
    },
}

[justinfx]

To be honest, I am not really sure what happens when you use cgo resources in a sync.Pool. I tried to find some information on it, but didn't come up with much more than someone saying "we were using cgo resources in a sync.Pool and it didn't play nice". I do know that sync.Pool clears the objects during each garbage collection, so the advantage would be to reuse allocation between each garbage collection.

Did profiling show that creating new wands each time and freeing them was a bottleneck? If so, maybe you should try a standard free list cache instead of sync.Pool and see if that fixes your issue.

Also, do you have an example of how you are reusing the wand from the pool? What operations do you call on the reused wand each time? Are you retaining any objects that were created from the wand, beyond the point when you put the wand back in the pool?

In my own experience using Imagick within a web-based image server, my implementation used a pool of workers to do image processing. Each worker would create and destroy wands each time, but I would only have, say 4 workers (or something matching the available cpus). I never used a free list or pool for the wands because I just figured creating a new wand is significantly less time than it takes to process images with it.

[fvm]

I implemented this thinking any re-use of the wand would be preferable over recreating and destroying one every time. I use a []byte represented as a type Image internally to store the blob and move the blob to and from the wand at the beginning and end (through defer) of every processing step, making sure to call func (mw *MagickWand) Clear():

// Get a wand and give it the data
func (i *Image) toWand() (w *imagick.MagickWand, err error) {
    w = wandPool.Get().(*imagick.MagickWand)

    w.Clear()

    err = w.ReadImageBlob(i.blob)
    if err != nil {
        logrus.Errorf("Error while reading blob to wand: %s", err)
        return
    }
    w.ResetIterator()

    return
}

// Retrieve the data from the wand and put it back
func (i *Image) doneWithMagickWand(w *imagick.MagickWand) {
    w.ResetIterator()
    i.blob = w.GetImagesBlob()
    w.Clear()
    wandPool.Put(w)
    return
}

Now, I've changed the Sync.Pool out for a straighforward NewMagickwand() and, importantly, a Destroy() and it does seem that letting the garbage collector sweep the pool without the wand being explictly destroyed was the cause of the unexpected signal. I've been throwing a few hundred images at it and no problems at all.

So, yeah, the idea of using Sync.Pool seemed attractive, if only to gain a tiny bit of performance increase (as in my case milliseconds count), but causes more problems than it's worth as it skips the Destroy() part of the cycle.

[justinfx]

Did profiling actually show a performance advantage to the sync pool?

Actually as of #80 (v2.2.0) MagickWand, along with other related types, had a finalizer added so that they would auto destroy when garbage collected. So calling Destroy manually only kills the C object sooner rather than later. Are you using >= 2.2.0 already?

Something must be getting reused after destruction with that sync Pool set up. Like I said, if profiling shows that you are wasting significant time creating and destroying wants compared to manipulating your images, you could see if a channel-based free list or similar would help. At least it's more predictable with the management of the objects since they never destroy.

I was wondering... If you were to reuse a single wand the way you do, in just a single goroutine looping 100s of times reading and clearing, do you see the problem?

[fvm]

As to the bottleneck, no there was no real bottleneck, but any increase of performance, in this case by using the Sync.Pool, seemed desirable. As that only seems to obfuscate matters in this case, I just removed it and resorted to just calling NewMagickWand() and Destroy().

Now, the troubling thing is that it did seem to fix the issue, it now turns out that, although decreased in frequency, the panic does still occur sometimes. So even without the pool, it still occurs.

The revision I'm using is f45c537 (v2.2.2). For completeness, here's the code which creates and clears wands and loads the image bytes to the wand (yes, the Clear()s are somewhat superfluous after removing the pool):

package renderer

import (

    "github.com/Sirupsen/logrus"

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

func init() {
    imagick.Initialize()
}

type Image struct {
    blob []byte
}

// Get a wand and give it the data
func (i *Image) toWand() (w *imagick.MagickWand, err error) {
    w = imagick.NewMagickWand()

    w.Clear()

    err = w.ReadImageBlob(i.blob)
    if err != nil {
        logrus.Errorf("Error while reading blob to wand: %s", err)
        return
    }
    w.ResetIterator()

    return
}

// Retrieve the data from the wand and destroy it
func (i *Image) doneWithMagickWand(w *imagick.MagickWand) {
    w.ResetIterator()
    i.blob = w.GetImagesBlob()
    w.Clear()
    w.Destroy()
    return
}

And here's an example of how I call it:

type jpeg struct {
    Image
}

// ... [SNIP] ...

func (j *jpeg) Trim(opt RenderOptions) error {
    defer toc(tic(), "Trim")

    if opt.Trimfactor <= 0 {
        logrus.Debugf("Skipping trim, trimfactor set to: %v", opt.Trimfactor)
        return nil
    }

    logrus.Debugf("Trimming image with a factor of %v", opt.Trimfactor)

    wand, err := j.toWand()
    defer j.doneWithMagickWand(wand)
    if err != nil {
        logrus.Error(err)
        return err
    }

    err = wand.TrimImage(float64(opt.Trimfactor))
    if err != nil {
        logrus.Errorf("Error during image trimming: %v", err)
        return err
    }

    return nil
}

[justinfx]

I guess I would need to create a runnable reproduction of this problem. I'm not sure why the wand is bad when you go to read a blob with it.

[rogierlommers]

What can we do to figure out the reason the wand is bad at the moment? And by the way, @justinfx , thanks for your help!!

[rogierlommers]

Some additional info: in our (I'm a colleague of @fvm ) case we indeed initiate imagick only once and every magic wand is being destroyed after use. This works for the cases that incoming bytes are jpg and we use imagick to create a jpg as well. When the incoming bytes are a pdf, then we still get the error.

Any additional suggestions? For example how to debug this?

[rogierlommers]

Well, the story continues. We can almost pinpoint it to Docker who f$cks up. When I run inside docker container --> panics, when I run on node itself (NOT in container) --> everything is smooth.

More info to come this Monday.

[justinfx]

@rogierlommers , that's interesting. Please keep me informed. Before you pointed out docker, I was going to suggest that it might have to do with the pdf delegate. That is, the libraries installed to satisfy pdf support. Because if it works great with JPG but then crashes within pdf, that would probably indicate it is somewhere in the plugin interactions.
Have you been able to run it from a debugger to catch the crash and inspect the C stack?

[justinfx]

Copying my reply from #96 as it might be helpful...

Re:
http://imagemagick.org/discourse-server/viewtopic.php?t=23365

Apparently you can set MAGICK_DEBUG to trace and see debug output from ImageMagick.

[fvm]

Cheers Justin, I was already considering compiling debug versions and what have you... I'll look into it

[justinfx]

That link seemed to indicate that it was only a runtime environment logging flag. I haven't tried it yet. But that would definitely be easier than needing to compile with debug.

[rogierlommers]

Here is a repo which pinpoints the problem: https://github.com/rogierlommers/go-panics

[justinfx]

Thanks for putting together the reproduction. I will try to find time to have a look at it.

[rogierlommers]

Thanks for putting together the reproduction. I will try to find time to have a look at it.

Sorry, please don't put effort in yet. Still not 100% able to reproduce.

[rogierlommers]

Also I think it is related to #96.