[issue1792] o(n*n) marshal.dumps performance for largish objects with patch

[Aaron Watters]

Aaron Watters added the comment:

also:

I just modified the code to do iterations using increasingly large data
sizes
and I see the kind of very unpleasant behaviour for the old implementation
(max time varies wildly from min time) that I saw in my more complex
program.  The new implementation doesn't have
these problems.   First the runs and then the modified code

runs

arw:/home/arw/test>
arw:/home/arw/test> ~/apache2/htdocs/pythonsrc/Python/python_old mtest1.pyold
old
0 40 elapsed max= 2.28881835938e-05 min= 4.76837158203e-06 ratio= 4.8
1 160 elapsed max= 1.59740447998e-05 min= 9.05990600586e-06 ratio=
1.76315789474
2 640 elapsed max= 2.40802764893e-05 min= 2.19345092773e-05 ratio=
1.09782608696
3 2560 elapsed max= 8.79764556885e-05 min= 3.981590271e-05 ratio=
2.20958083832
4 10240 elapsed max= 0.000290155410767 min= 0.000148057937622 ratio=
1.95974235105
5 40960 elapsed max= 0.000867128372192 min= 0.00060510635376 ratio=
1.43301812451
6 163840 elapsed max= 0.00739598274231 min= 0.00339317321777 ratio=
2.17966554244
7 655360 elapsed max= 0.0883929729462 min= 0.0139379501343 ratio=
6.34189189189
8 2621440 elapsed max= 1.69851398468 min= 0.0547370910645 ratio=
31.0304028155
9 10485760 elapsed max= 9.98945093155 min= 0.213104963303 ratio=
46.875730986
10 41943040 elapsed max= 132.281101942 min= 0.834150075912 ratio=
158.581897625
arw:/home/arw/test> ~/apache2/htdocs/pythonsrc/Python/python mtest1.py new
new
0 40 elapsed max= 2.19345092773e-05 min= 5.00679016113e-06 ratio=
4.38095238095
1 160 elapsed max= 1.00135803223e-05 min= 9.05990600586e-06 ratio=
1.10526315789
2 640 elapsed max= 3.19480895996e-05 min= 1.28746032715e-05 ratio=
2.48148148148
3 2560 elapsed max= 5.69820404053e-05 min= 3.981590271e-05 ratio=
1.43113772455
4 10240 elapsed max= 0.000186920166016 min= 0.000138998031616 ratio=
1.34476843911
5 40960 elapsed max= 0.00355315208435 min= 0.000746965408325 ratio=
4.75678263645
6 163840 elapsed max= 0.00326490402222 min= 0.00304794311523 ratio=
1.07118272841
7 655360 elapsed max= 0.0127630233765 min= 0.0122020244598 ratio=
1.04597588855
8 2621440 elapsed max= 0.0511522293091 min= 0.0484230518341 ratio=
1.05636112082
9 10485760 elapsed max= 0.198891878128 min= 0.187420129776 ratio=
1.06120873124
10 41943040 elapsed max= 0.758435964584 min= 0.729014158249 ratio=
1.04035834696
arw:/home/arw/test>

Above high ratio numbers indicate strange and unpleasant performance
variance.
For iteration 7 and higher the old implementation has a much
worse max time performance than the new one.

Here is the test code:

def test():
    from marshal import dumps
    from time import time
    size = 10
    for i in range(11):
        size = size*4
        testString = "abc"*size
        #print "now testing", i, size
        minelapsed = None
        for j in range(11):
            now = time()
            dump = dumps(testString)
            elapsed = time()-now
            if minelapsed is None:
                minelapsed = elapsed
                maxelapsed = elapsed
            else:
                minelapsed = min(elapsed, minelapsed)
                maxelapsed = max(elapsed, maxelapsed)
        print i, size, "elapsed max=", maxelapsed, "min=", minelapsed,
"ratio=", maxelapsed/minelapsed

if __name__=="__main__":
    import sys
    print sys.argv[1]
    test()

-- Aaron Watters

On Jan 11, 2008 10:14 AM, Aaron Watters < report at bugs.python.org> wrote:

>
> Aaron Watters added the comment:
>
> Facundo
>
> 1) the +1024 was an accelerator to jump up to over 1k at the first resize.
> I think it's a good idea or at least doesn't hurt.
>
> 2) Here is an example program:
>
> def test():
>    from marshal import dumps
>    from time import time
>    testString = "abc"*100000000
>    print "now testing"
>    now = time()
>    dump = dumps(testString)
>    elapsed = time()-now
>    print "elapsed", elapsed
>
> if __name__=="__main__":
>    test()
>
> Here are two runs: the first with the old marshal and the second with the
> patched marshal.  The second is
> better than 2* faster than the first.
>
> arw:/home/arw/test> ~/apache2/htdocs/pythonsrc/Python/python_old mtest1.py
> now testing
> elapsed 4.13367795944
> arw:/home/arw/test> ~/apache2/htdocs/pythonsrc/Python/python mtest1.py
> now testing
> elapsed 1.7495341301
> arw:/home/arw/test>
>
> The example that inspired this research was very complicated and involved
> millions of calls to dumps
> which caused a number of anomalies (system calls went berzerk for some
> reason, maybe paging).
>
>   -- Aaron Watters
>
> On Jan 11, 2008 9:25 AM, Facundo Batista <report at bugs.python.org> wrote:
>
> >
> > Facundo Batista added the comment:
> >
> > Why not just double the size? The "doubling + 1024" address some
> > specific issue? If so, it should be commented.
> >
> > Also, do you have an example of a marshal.dumps() that suffers from this
> > issue?
> >
> > Thank you!
> >
> > ----------
> > nosy: +facundobatista
> >
> > __________________________________
> > Tracker <report at bugs.python.org>
> > <http://bugs.python.org/issue1792>
> > __________________________________
> >
>
> Added file: http://bugs.python.org/file9124/unnamed
>
> __________________________________
> Tracker <report at bugs.python.org>
> <http://bugs.python.org/issue1792>
> __________________________________
>

Added file: http://bugs.python.org/file9125/unnamed

__________________________________
Tracker <report at bugs.python.org>
<http://bugs.python.org/issue1792>
__________________________________
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: unnamed
Url: http://mail.python.org/pipermail/python-bugs-list/attachments/20080111/f50e5c47/attachment-0001.txt