Performance

[ouhouhsami]

Hello,

While updating from 2.0.1 to 3.1.2 version (or any of the 3.0 versions), I loose a lot of performance, JUST when I first reach a page of my website after restarting the server (on production), or using python manage.py runserver.

For the moment I didn't investigate much, but is there an initialisation process in django_select2 app done a "first loading" ? And which has changed between 3.0 versions and 2.0.1 version ?

Regards,

[ouhouhsami]

So, I set debug level for django_select2 to INFO, and I get the answer, it's the registration process for autofield. In my case, I have
INFO Registering auto field: works.fields.WorkSelect2Field
...
The "funny" thing is that the registration of all of these fields is done one time a the begining, even if the view I request doesn't need any of them.

[ouhouhsami]

Also, for convenience in development process, if the registering function must be called once, at the begining, it should be great, but also important, to keep a state of what it does, and not always recall the registering (like having a 'cache' for dev purpose ...) ?

[applegrew]

Hi @ouhouhsami, thanks for finding the cause. Whenever an Auto field is instantiated then it registers itself in a central list. However, if that any other instance of that class has already registered itself then the new instance is not added to the list.

So here what happens. Autofield -> Register me -> A unique Id is generated and returned (if that class is already registered then registered unique id for this class is returned) -> Auto field now stores this unique Id.

Now whenever the Autofield is rendered then it will pass on this unique Id to rendered markup. The JS helper will send this Id during Ajax lookup. The central View uses the Id to find the appropriate instance to serve the request.

Ideally the usual code of a form is like:-

class ContactForm(forms.Form):
    subject = forms.CharField(max_length=100)
    message = forms.CharField()
    sender = AnAutoField()

So, when Python parses the above definition it also instantiates AnAutoField, triggering the registration process.

[ouhouhsami]

Thanks for your explanation. The thing is that in development process, I use 3/4 autofield, and the generation of the id take a lot of time the first request (about 30 seconds ...)

[applegrew]

Well then I will need your help then... How many Auto field instances do you have (the count)? I can then profile the time taken when a new one is generated.. and when existing ones are returned.. Will see then where we can optimize. Currently the registration process is minimal. I am suspecting the Dict structure could be causing this delay, as it needs to look inside it first. If that is the case then it will mean delay in serving all auto lookup requests.

[ouhouhsami]

Ok,

Here are all my logs

INFO Registering auto field: works.fields.WorkSelect2Field
INFO Registering new field: works.fields.WorkSelect2Field; With actual id: 0:2012-10-12 04:48:41.540936
INFO Registering auto field: utils.fields.EquipmentReferenceSelect2Field
INFO Registering new field: utils.fields.EquipmentReferenceSelect2Field; With actual id: 1:2012-10-12 04:48:48.628363
INFO Registering auto field: brahms2.works.admin.ComposerChoices
INFO Registering new field: brahms2.works.admin.ComposerChoices; With actual id: 3:2012-10-12 04:48:56.810984
INFO Registering auto field: works.fields.WorkSelect2Field
INFO Field already registered: works.fields.WorkSelect2Field; With actual id: 0:2012-10-12 04:48:41.540936
INFO Registering auto field: utils.fields.EquipmentReferenceSelect2Field
INFO Field already registered: utils.fields.EquipmentReferenceSelect2Field; With actual id: 1:2012-10-12 04:48:48.628363
INFO Registering auto field: works.fields.VersionSelect2Field
INFO Registering new field: works.fields.VersionSelect2Field; With actual id: 4:2012-10-12 04:49:01.668977

So I have 4 auto fields.
The thing which take time is, for each, the 'registering new field'

And here is my code for the WorkSelect2Field

class WorkSelect2Field(AutoModelSelect2Field):
    """
    Work Select2 field for creation version form

    """
    queryset = Work.objects.all()  
    search_fields = ['title', ]

    def get_results(self, request, term, page, context):
        works = Work.objects.all().filter(title__icontains=term)
        res = [(work.id, "<i>%s</i> %s [id:%s]" % (work.title, work.composers.all()[0], work.id),)
            for work in works]
        return (NO_ERR_RESP, False, res, )

(As you see, I have a related lookup in get_results, but this isn't called on init, I tested)
I just remove the all() from queryset, and, (of course) it changes nothing.

[applegrew]

Of course get_results() won't be invoked. The registration is done from __init__(). 30s for four registration is too much. I will need to profile them.

[applegrew]

Well I see about 0.15ms time taken per registration. Your 30s should incude many other stuffs which may not be related to Django Select2. I have made a commit just now to print the time taken in registration. This can be turned on if you set the logger to DEBUG.

[ouhouhsami]

Well, I use your last version, and here is what I get :

INFO Registering auto field: works.fields.WorkSelect2Field
INFO Registering new field: works.fields.WorkSelect2Field; With actual id: 0:2012-10-15 05:37:44.302236
DEBUG Time taken by synced_f: 0.112 ms
INFO Registering auto field: utils.fields.EquipmentReferenceSelect2Field
INFO Registering new field: utils.fields.EquipmentReferenceSelect2Field; With actual id: 1:2012-10-15 05:37:47.961753
DEBUG Time taken by synced_f: 0.125 ms
INFO Registering auto field: brahms2.works.admin.ComposerChoices
INFO Registering new field: brahms2.works.admin.ComposerChoices; With actual id: 3:2012-10-15 05:37:52.688338
DEBUG Time taken by synced_f: 0.127 ms
INFO Registering auto field: works.fields.VersionSelect2Field
INFO Registering new field: works.fields.VersionSelect2Field; With actual id: 4:2012-10-15 05:37:57.411727
DEBUG Time taken by synced_f: 0.102 ms

The thing is that the debug info is short, the problem is 'just after' : between DEBUG Time taken by synced_f: 0.112 ms and INFO Registering auto field: utils.fields.EquipmentReferenceSelect2Field there is an average 5 seconds (I guess) time lapse.

[ouhouhsami]

Also, I found some kind of a weird bug.

If I add, in my case a new Work, next, in a form where I use a WorkSelect2Field, I am able to find it (the Work instance I previously created), but when I save the object (containing reference to the Work instance previously created), the field WorkSelect2Field is empty, even if the data is well saved.

If after that I restart server (development or production server), the Work instance is now present in the WorkSelect2Field.

It seems like all values available for WorkSelect2Field are kept in a tmp file that is created with the relaunch of the server. But this values are only the ones which where available when the server started, not the one that have been added after.

[applegrew]

DEBUG Time taken by synced_f: 0.112 ms is the time taken to register INFO Registering new field: works.fields.WorkSelect2Field. So, in little more than 0.1ms WorkSelect2Field should have been registered. By the time time you see INFO Registering auto field: utils.fields.EquipmentReferenceSelect2Field, many other codes, not necessarily in Django Select2 could have been running. Please try find out what else could be running in-between, because I am unable to replicate this in the testapp.

As far as the bug goes I will need to investigate that. Are you using app that caches QuerySet results or something like that? Django Select2 does not create any tmp file. This app doesn't try to optimize how data are fetched.

[ouhouhsami]

Ok, I have a look now at this, but, as I wrote at the begining of this issue, the problem doesn't occur with previous versions of django-select2 (the 2.0.1)

[applegrew]

Ok. I will check again. You also please check and let me know if you find anything interesting.

[ouhouhsami]

So, my first investigation: my problem comes from here : https://github.com/applegrew/django-select2/blob/master/django_select2/fields.py#L431

The 2 things I talked about here have the same issue:

1. this line set definitively choices available (even if we create a new instance after registration)
2. it takes a lot of time with model having a lot of instance to register the field

Regards,

[applegrew]

I haven't yet been able to look into this because of my work, and I am going on two weeks vacation. So, there will be considerable delay to fix this.