[pypy-dev] Pypy garbage collection
Maciej Fijalkowski
fijall at gmail.com
Mon Mar 17 17:39:13 CET 2014
not sure how more we can help without looking into the code
On Mon, Mar 17, 2014 at 6:05 PM, Martin Koch <mak at issuu.com> wrote:
> Thanks :)
>
> /Martin
>
>
>> On 17/03/2014, at 16.41, Maciej Fijalkowski <fijall at gmail.com> wrote:
>>
>> ok.
>>
>> so as you can probably see, the max is not that big, which means the
>> GC is really incremental. What happens is you get tons of garbage that
>> survives minor collection every now and then. I don't exactly know
>> why, but you should look what objects can potentially survive for too
>> long.
>>
>>> On Mon, Mar 17, 2014 at 5:37 PM, Martin Koch <mak at issuu.com> wrote:
>>> Ah - it just occured to me that the first runs may be slow anyway: Since we
>>> take the average of the last 100 runs as the benchmark, then the first 100
>>> runs are not classified as slow. Indeed, the first three runs with many
>>> collections are in the first 100 runs.
>>>
>>>
>>>> On Mon, Mar 17, 2014 at 4:35 PM, Martin Koch <mak at issuu.com> wrote:
>>>>
>>>> Here are the total and max times in millions of units; 30000 units is
>>>> approximately 13 seconds. I have extracted the runs where there are many
>>>> gc-collect-steps. These are in execution order, so the first runs with many
>>>> gc-collect-steps aren't slow.
>>>>
>>>> Totals: gc-minor:418 gc-minor-walkroots:0 gc-collect-step:28797 Max:
>>>> gc-minor:10 gc-collect-step:247
>>>> Totals: gc-minor:562 gc-minor-walkroots:0 gc-collect-step:30282 Max:
>>>> gc-minor:10 gc-collect-step:245
>>>> Totals: gc-minor:434 gc-minor-walkroots:0 gc-collect-step:31040 Max:
>>>> gc-minor:11 gc-collect-step:244
>>>> Totals: gc-minor:417 slow:1 gc-minor-walkroots:0 gc-collect-step:31270
>>>> Max: gc-minor:17 gc-collect-step:244
>>>> Totals: gc-minor:435 slow:1 gc-minor-walkroots:0 gc-collect-step:30365
>>>> Max: gc-minor:11 gc-collect-step:248
>>>> Totals: gc-minor:389 slow:1 gc-minor-walkroots:0 gc-collect-step:31235
>>>> Max: gc-minor:8 gc-collect-step:299
>>>> Totals: gc-minor:434 slow:1 gc-minor-walkroots:0 gc-collect-step:31124
>>>> Max: gc-minor:11 gc-collect-step:246
>>>> Totals: gc-minor:386 slow:1 gc-minor-walkroots:0 gc-collect-step:30541
>>>> Max: gc-minor:8 gc-collect-step:244
>>>> Totals: gc-minor:410 slow:1 gc-minor-walkroots:0 gc-collect-step:31427
>>>> Max: gc-minor:36 gc-collect-step:248
>>>> Totals: gc-minor:390 slow:1 gc-minor-walkroots:0 gc-collect-step:30743
>>>> Max: gc-minor:8 gc-collect-step:244
>>>> Totals: gc-minor:380 slow:1 gc-minor-walkroots:0 gc-collect-step:30207
>>>> Max: gc-minor:8 gc-collect-step:245
>>>> Totals: gc-minor:387 slow:1 gc-minor-walkroots:0 gc-collect-step:30837
>>>> Max: gc-minor:8 gc-collect-step:244
>>>> Totals: gc-minor:412 slow:1 gc-minor-walkroots:0 gc-collect-step:30898
>>>> Max: gc-minor:38 gc-collect-step:244
>>>> Totals: gc-minor:415 slow:1 gc-minor-walkroots:0 gc-collect-step:30407
>>>> Max: gc-minor:23 gc-collect-step:245
>>>> Totals: gc-minor:380 slow:1 gc-minor-walkroots:0 gc-collect-step:30591
>>>> Max: gc-minor:8 gc-collect-step:246
>>>> Totals: gc-minor:387 slow:1 gc-minor-walkroots:0 gc-collect-step:31193
>>>> Max: gc-minor:9 gc-collect-step:244
>>>> Totals: gc-minor:379 slow:1 gc-minor-walkroots:0 gc-collect-step:30026
>>>> Max: gc-minor:8 gc-collect-step:246
>>>> Totals: gc-minor:388 slow:1 gc-minor-walkroots:0 gc-collect-step:31179
>>>> Max: gc-minor:8 gc-collect-step:248
>>>> Totals: gc-minor:378 slow:1 gc-minor-walkroots:0 gc-collect-step:30674
>>>> Max: gc-minor:8 gc-collect-step:250
>>>> Totals: gc-minor:385 slow:1 gc-minor-walkroots:0 gc-collect-step:30413
>>>> Max: gc-minor:8 gc-collect-step:245
>>>> Totals: gc-minor:915 slow:1 gc-minor-walkroots:0 gc-collect-step:30830
>>>> Max: gc-minor:543 gc-collect-step:244
>>>> Totals: gc-minor:405 slow:1 gc-minor-walkroots:0 gc-collect-step:31153
>>>> Max: gc-minor:20 gc-collect-step:246
>>>> Totals: gc-minor:408 slow:1 gc-minor-walkroots:0 gc-collect-step:29815
>>>> Max: gc-minor:25 gc-collect-step:245
>>>>
>>>> Thanks,
>>>> /Martin
>>>>
>>>>
>>>>> On Mon, Mar 17, 2014 at 3:24 PM, Martin Koch <mak at issuu.com> wrote:
>>>>>
>>>>> Ah. I had misunderstood. I'll get back to you on that :) thanks
>>>>>
>>>>> /Martin
>>>>>
>>>>>
>>>>>> On 17/03/2014, at 15.21, Maciej Fijalkowski <fijall at gmail.com> wrote:
>>>>>>
>>>>>> eh, this is not what I need
>>>>>>
>>>>>> I need a max of TIME it took for a gc-minor and the TOTAL time it took
>>>>>> for a gc-minor (per query) (ideally same for gc-walkroots and
>>>>>> gc-collect-step)
>>>>>>
>>>>>>> On Mon, Mar 17, 2014 at 4:19 PM, Martin Koch <mak at issuu.com> wrote:
>>>>>>> Here are the collated results of running each query. For each run, I
>>>>>>> count
>>>>>>> how many of each of the pypy debug lines i get. I.e. there were 668
>>>>>>> runs
>>>>>>> that printed 58 loglines that contain "{gc-minor" which was eventually
>>>>>>> followed by "gc-minor}". I have also counted if the query was slow;
>>>>>>> interestingly, not all the queries with many gc-minors were slow (but
>>>>>>> all
>>>>>>> slow queries had a gc-minor).
>>>>>>>
>>>>>>> Please let me know if this is unclear :)
>>>>>>>
>>>>>>> 668 gc-minor:58 gc-minor-walkroots:58
>>>>>>> 10 gc-minor:58 gc-minor-walkroots:58 gc-collect-step:5
>>>>>>> 140 gc-minor:59 gc-minor-walkroots:59
>>>>>>> 1 gc-minor:8441 gc-minor-walkroots:8441 gc-collect-step:8403
>>>>>>> 1 gc-minor:9300 gc-minor-walkroots:9300 gc-collect-step:9249
>>>>>>> 9 gc-minor:9643 slow:1 gc-minor-walkroots:9643
>>>>>>> gc-collect-step:9589
>>>>>>> 1 gc-minor:9644 slow:1 gc-minor-walkroots:9644
>>>>>>> gc-collect-step:9590
>>>>>>> 10 gc-minor:9647 slow:1 gc-minor-walkroots:9647
>>>>>>> gc-collect-step:9609
>>>>>>> 1 gc-minor:9663 gc-minor-walkroots:9663 gc-collect-step:9614
>>>>>>> 1 jit-backend-dump:5 gc-minor:58 gc-minor-walkroots:58
>>>>>>> 1 jit-log-compiling-loop:1 gc-collect-step:8991
>>>>>>> jit-backend-dump:78
>>>>>>> jit-backend:3 jit-log-noopt-loop:6 jit-log-virtualstate:3
>>>>>>> gc-minor:9030
>>>>>>> jit-tracing:3 gc-minor-walkroots:9030 jit-optimize:6
>>>>>>> jit-log-short-preamble:2 jit-backend-addr:3 jit-log-opt-loop:1
>>>>>>> jit-mem-looptoken-alloc:3 jit-abort:3 jit-log-rewritten-bridge:2
>>>>>>> jit-log-rewritten-loop:1 jit-log-opt-bridge:2
>>>>>>> jit-log-compiling-bridge:2
>>>>>>> jit-resume:84
>>>>>>> 1 jit-log-compiling-loop:1 jit-backend-dump:13 jit-backend:1
>>>>>>> jit-log-noopt-loop:2 gc-minor:60 jit-tracing:1 gc-minor-walkroots:60
>>>>>>> jit-optimize:2 jit-log-short-preamble:1 jit-backend-addr:1
>>>>>>> jit-log-opt-loop:1 jit-mem-looptoken-alloc:1 jit-log-rewritten-loop:1
>>>>>>> jit-resume:14
>>>>>>> 1 jit-log-compiling-loop:1 jit-backend-dump:73 jit-backend:3
>>>>>>> jit-log-noopt-loop:6 jit-log-virtualstate:3 gc-minor:60 jit-tracing:3
>>>>>>> gc-minor-walkroots:60 jit-optimize:6 jit-log-short-preamble:2
>>>>>>> jit-backend-addr:3 jit-log-opt-loop:1 jit-mem-looptoken-alloc:3
>>>>>>> jit-abort:3
>>>>>>> jit-log-rewritten-bridge:2 jit-log-rewritten-loop:1
>>>>>>> jit-log-opt-bridge:2
>>>>>>> jit-log-compiling-bridge:2 jit-resume:84
>>>>>>> 2 jit-log-compiling-loop:1 jit-backend-dump:78 jit-backend:3
>>>>>>> jit-log-noopt-loop:6 jit-log-virtualstate:3 gc-minor:61 jit-tracing:3
>>>>>>> gc-minor-walkroots:61 jit-optimize:6 jit-log-short-preamble:2
>>>>>>> jit-backend-addr:3 jit-log-opt-loop:1 jit-mem-looptoken-alloc:3
>>>>>>> jit-abort:3
>>>>>>> jit-log-rewritten-bridge:2 jit-log-rewritten-loop:1
>>>>>>> jit-log-opt-bridge:2
>>>>>>> jit-log-compiling-bridge:2 jit-resume:84
>>>>>>> 1 jit-log-short-preamble:2 jit-log-compiling-loop:2
>>>>>>> jit-backend-dump:92 jit-log-noopt-loop:7 jit-log-virtualstate:3
>>>>>>> gc-minor:61
>>>>>>> jit-tracing:4 gc-minor-walkroots:61 jit-optimize:7 jit-backend:4
>>>>>>> jit-backend-addr:4 jit-log-opt-loop:2 jit-mem-looptoken-alloc:4
>>>>>>> jit-abort:3
>>>>>>> jit-log-rewritten-bridge:2 jit-log-rewritten-loop:2
>>>>>>> jit-log-opt-bridge:2
>>>>>>> jit-log-compiling-bridge:2 jit-resume:104
>>>>>>>
>>>>>>>
>>>>>>> Thanks,
>>>>>>> /Martin
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> On Mon, Mar 17, 2014 at 2:23 PM, Maciej Fijalkowski <fijall at gmail.com>
>>>>>>> wrote:
>>>>>>>>
>>>>>>>> On Mon, Mar 17, 2014 at 3:20 PM, Maciej Fijalkowski
>>>>>>>> <fijall at gmail.com>
>>>>>>>> wrote:
>>>>>>>>> are you *sure* it's the walkroots that take that long and not
>>>>>>>>> something else (like gc-minor)? More of those mean that you allocate
>>>>>>>>> a
>>>>>>>>> lot more surviving objects. Can you do two things:
>>>>>>>>>
>>>>>>>>> a) take a max of gc-minor (and gc-minor-stackwalk), per request
>>>>>>>>> b) take the sum of those
>>>>>>>>>
>>>>>>>>> and plot them
>>>>>>>>
>>>>>>>> ^^^ or just paste the results actually
>>>>>>>>
>>>>>>>>>
>>>>>>>>>> On Mon, Mar 17, 2014 at 3:18 PM, Martin Koch <mak at issuu.com> wrote:
>>>>>>>>>> Well, then it works out to around 2.5GHz, which seems reasonable.
>>>>>>>>>> But
>>>>>>>>>> it
>>>>>>>>>> doesn't alter the conclusion from the previous email: The slow
>>>>>>>>>> queries
>>>>>>>>>> then
>>>>>>>>>> all have a duration around 34*10^9 units, 'normal' queries 1*10^9
>>>>>>>>>> units, or
>>>>>>>>>> .4 seconds at this conversion. Also, the log shows that a slow
>>>>>>>>>> query
>>>>>>>>>> performs many more gc-minor operations than a 'normal' one: 9600
>>>>>>>>>> gc-collect-step/gc-minor/gc-minor-walkroots operations vs 58.
>>>>>>>>>>
>>>>>>>>>> So the question becomes: Why do we get this large spike in
>>>>>>>>>> gc-minor-walkroots, and, in particular, is there any way to avoid
>>>>>>>>>> it :)
>>>>>>>>>> ?
>>>>>>>>>>
>>>>>>>>>> Thanks,
>>>>>>>>>> /Martin
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> On Mon, Mar 17, 2014 at 1:53 PM, Maciej Fijalkowski
>>>>>>>>>> <fijall at gmail.com>
>>>>>>>>>> wrote:
>>>>>>>>>>>
>>>>>>>>>>> I think it's the cycles of your CPU
>>>>>>>>>>>
>>>>>>>>>>>> On Mon, Mar 17, 2014 at 2:48 PM, Martin Koch <mak at issuu.com>
>>>>>>>>>>>> wrote:
>>>>>>>>>>>> What is the unit? Perhaps I'm being thick here, but I can't
>>>>>>>>>>>> correlate it
>>>>>>>>>>>> with seconds (which the program does print out). Slow runs are
>>>>>>>>>>>> around 13
>>>>>>>>>>>> seconds, but are around 34*10^9(dec), 0x800000000 timestamp units
>>>>>>>>>>>> (e.g.
>>>>>>>>>>>> from
>>>>>>>>>>>> 0x2b994c9d31889c to 0x2b9944ab8c4f49).
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> On Mon, Mar 17, 2014 at 12:09 PM, Maciej Fijalkowski
>>>>>>>>>>>> <fijall at gmail.com>
>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>
>>>>>>>>>>>>> The number of lines is nonsense. This is a timestamp in hex.
>>>>>>>>>>>>>
>>>>>>>>>>>>> On Mon, Mar 17, 2014 at 12:46 PM, Martin Koch <mak at issuu.com>
>>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>> Based On Maciej's suggestion, I tried the following
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> PYPYLOG=- pypy mem.py 10000000 > out
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> This generates a logfile which looks something like this
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> start-->
>>>>>>>>>>>>>> [2b99f1981b527e] {gc-minor
>>>>>>>>>>>>>> [2b99f1981ba680] {gc-minor-walkroots
>>>>>>>>>>>>>> [2b99f1981c2e02] gc-minor-walkroots}
>>>>>>>>>>>>>> [2b99f19890d750] gc-minor}
>>>>>>>>>>>>>> [snip]
>>>>>>>>>>>>>> ...
>>>>>>>>>>>>>> <--stop
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> It turns out that the culprit is a lot of MINOR collections.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> I base this on the following observations:
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> I can't understand the format of the timestamp on each logline
>>>>>>>>>>>>>> (the
>>>>>>>>>>>>>> "[2b99f1981b527e]"). From what I can see in the code, this
>>>>>>>>>>>>>> should
>>>>>>>>>>>>>> be
>>>>>>>>>>>>>> output
>>>>>>>>>>>>>> from time.clock(), but that doesn't return a number like that
>>>>>>>>>>>>>> when I
>>>>>>>>>>>>>> run
>>>>>>>>>>>>>> pypy interactively
>>>>>>>>>>>>>> Instead, I count the number of debug lines between start--> and
>>>>>>>>>>>>>> the
>>>>>>>>>>>>>> corresponding <--stop.
>>>>>>>>>>>>>> Most runs have a few hundred lines of output between start/stop
>>>>>>>>>>>>>> All slow runs have very close to 57800 lines out output between
>>>>>>>>>>>>>> start/stop
>>>>>>>>>>>>>> One such sample does 9609 gc-collect-step operations, 9647
>>>>>>>>>>>>>> gc-minor
>>>>>>>>>>>>>> operations, and 9647 gc-minor-walkroots operations.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> Thanks,
>>>>>>>>>>>>>> /Martin
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> On Mon, Mar 17, 2014 at 8:21 AM, Maciej Fijalkowski
>>>>>>>>>>>>>> <fijall at gmail.com>
>>>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> there is an environment variable PYPYLOG=gc:- (where - is
>>>>>>>>>>>>>>> stdout)
>>>>>>>>>>>>>>> which will do that for you btw.
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> maybe you can find out what's that using profiling or
>>>>>>>>>>>>>>> valgrind?
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> On Sun, Mar 16, 2014 at 11:34 PM, Martin Koch <mak at issuu.com>
>>>>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>>>> I have tried getting the pypy source and building my own
>>>>>>>>>>>>>>>> version
>>>>>>>>>>>>>>>> of
>>>>>>>>>>>>>>>> pypy. I
>>>>>>>>>>>>>>>> have modified
>>>>>>>>>>>>>>>> rpython/memory/gc/incminimark.py:major_collection_step()
>>>>>>>>>>>>>>>> to
>>>>>>>>>>>>>>>> print out when it starts and when it stops. Apparently, the
>>>>>>>>>>>>>>>> slow
>>>>>>>>>>>>>>>> queries
>>>>>>>>>>>>>>>> do
>>>>>>>>>>>>>>>> NOT occur during major_collection_step; at least, I have not
>>>>>>>>>>>>>>>> observed
>>>>>>>>>>>>>>>> major
>>>>>>>>>>>>>>>> step output during a query execution. So, apparently,
>>>>>>>>>>>>>>>> something
>>>>>>>>>>>>>>>> else
>>>>>>>>>>>>>>>> is
>>>>>>>>>>>>>>>> blocking. This could be another aspect of the GC, but it
>>>>>>>>>>>>>>>> could
>>>>>>>>>>>>>>>> also
>>>>>>>>>>>>>>>> be
>>>>>>>>>>>>>>>> anything else.
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Just to be sure, I have tried running the same application in
>>>>>>>>>>>>>>>> python
>>>>>>>>>>>>>>>> with
>>>>>>>>>>>>>>>> garbage collection disabled. I don't see the problem there,
>>>>>>>>>>>>>>>> so
>>>>>>>>>>>>>>>> it
>>>>>>>>>>>>>>>> is
>>>>>>>>>>>>>>>> somehow
>>>>>>>>>>>>>>>> related to either GC or the runtime somehow.
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Cheers,
>>>>>>>>>>>>>>>> /Martin
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> On Fri, Mar 14, 2014 at 4:19 PM, Martin Koch <mak at issuu.com>
>>>>>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> We have hacked up a small sample that seems to exhibit the
>>>>>>>>>>>>>>>>> same
>>>>>>>>>>>>>>>>> issue.
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> We basically generate a linked list of objects. To increase
>>>>>>>>>>>>>>>>> connectedness,
>>>>>>>>>>>>>>>>> elements in the list hold references (dummy_links) to 10
>>>>>>>>>>>>>>>>> randomly
>>>>>>>>>>>>>>>>> chosen
>>>>>>>>>>>>>>>>> previous elements in the list.
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> We then time a function that traverses 50000 elements from
>>>>>>>>>>>>>>>>> the
>>>>>>>>>>>>>>>>> list
>>>>>>>>>>>>>>>>> from a
>>>>>>>>>>>>>>>>> random start point. If the traversal reaches the end of the
>>>>>>>>>>>>>>>>> list,
>>>>>>>>>>>>>>>>> we
>>>>>>>>>>>>>>>>> instead
>>>>>>>>>>>>>>>>> traverse one of the dummy links. Thus, exactly 50K elements
>>>>>>>>>>>>>>>>> are
>>>>>>>>>>>>>>>>> traversed
>>>>>>>>>>>>>>>>> every time. To generate some garbage, we build a list
>>>>>>>>>>>>>>>>> holding
>>>>>>>>>>>>>>>>> the
>>>>>>>>>>>>>>>>> traversed
>>>>>>>>>>>>>>>>> elements and a dummy list of characters.
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Timings for the last 100 runs are stored in a circular
>>>>>>>>>>>>>>>>> buffer. If
>>>>>>>>>>>>>>>>> the
>>>>>>>>>>>>>>>>> elapsed time for the last run is more than twice the average
>>>>>>>>>>>>>>>>> time,
>>>>>>>>>>>>>>>>> we
>>>>>>>>>>>>>>>>> print
>>>>>>>>>>>>>>>>> out a line with the elapsed time, the threshold, and the 90%
>>>>>>>>>>>>>>>>> runtime
>>>>>>>>>>>>>>>>> (we
>>>>>>>>>>>>>>>>> would like to see that the mean runtime does not increase
>>>>>>>>>>>>>>>>> with
>>>>>>>>>>>>>>>>> the
>>>>>>>>>>>>>>>>> number of
>>>>>>>>>>>>>>>>> elements in the list, but that the max time does increase
>>>>>>>>>>>>>>>>> (linearly
>>>>>>>>>>>>>>>>> with the
>>>>>>>>>>>>>>>>> number of object, i guess); traversing 50K elements should
>>>>>>>>>>>>>>>>> be
>>>>>>>>>>>>>>>>> independent of
>>>>>>>>>>>>>>>>> the memory size).
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> We have tried monitoring memory consumption by external
>>>>>>>>>>>>>>>>> inspection,
>>>>>>>>>>>>>>>>> but
>>>>>>>>>>>>>>>>> cannot consistently verify that memory is deallocated at the
>>>>>>>>>>>>>>>>> same
>>>>>>>>>>>>>>>>> time
>>>>>>>>>>>>>>>>> that
>>>>>>>>>>>>>>>>> we see slow requests. Perhaps the pypy runtime doesn't
>>>>>>>>>>>>>>>>> always
>>>>>>>>>>>>>>>>> return
>>>>>>>>>>>>>>>>> freed
>>>>>>>>>>>>>>>>> pages back to the OS?
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Using top, we observe that 10M elements allocates around
>>>>>>>>>>>>>>>>> 17GB
>>>>>>>>>>>>>>>>> after
>>>>>>>>>>>>>>>>> building, 20M elements 26GB, 30M elements 28GB (and grows to
>>>>>>>>>>>>>>>>> 35GB
>>>>>>>>>>>>>>>>> shortly
>>>>>>>>>>>>>>>>> after building).
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Here is output from a few runs with different number of
>>>>>>>>>>>>>>>>> elements:
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> pypy mem.py 10000000
>>>>>>>>>>>>>>>>> start build
>>>>>>>>>>>>>>>>> end build 84.142424
>>>>>>>>>>>>>>>>> that took a long time elapsed: 13.230586 slow_threshold:
>>>>>>>>>>>>>>>>> 1.495401
>>>>>>>>>>>>>>>>> 90th_quantile_runtime: 0.421558
>>>>>>>>>>>>>>>>> that took a long time elapsed: 13.016531 slow_threshold:
>>>>>>>>>>>>>>>>> 1.488160
>>>>>>>>>>>>>>>>> 90th_quantile_runtime: 0.423441
>>>>>>>>>>>>>>>>> that took a long time elapsed: 13.032537 slow_threshold:
>>>>>>>>>>>>>>>>> 1.474563
>>>>>>>>>>>>>>>>> 90th_quantile_runtime: 0.419817
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> pypy mem.py 20000000
>>>>>>>>>>>>>>>>> start build
>>>>>>>>>>>>>>>>> end build 180.823105
>>>>>>>>>>>>>>>>> that took a long time elapsed: 27.346064 slow_threshold:
>>>>>>>>>>>>>>>>> 2.295146
>>>>>>>>>>>>>>>>> 90th_quantile_runtime: 0.434726
>>>>>>>>>>>>>>>>> that took a long time elapsed: 26.028852 slow_threshold:
>>>>>>>>>>>>>>>>> 2.283927
>>>>>>>>>>>>>>>>> 90th_quantile_runtime: 0.374190
>>>>>>>>>>>>>>>>> that took a long time elapsed: 25.432279 slow_threshold:
>>>>>>>>>>>>>>>>> 2.279631
>>>>>>>>>>>>>>>>> 90th_quantile_runtime: 0.371502
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> pypy mem.py 30000000
>>>>>>>>>>>>>>>>> start build
>>>>>>>>>>>>>>>>> end build 276.217811
>>>>>>>>>>>>>>>>> that took a long time elapsed: 40.993855 slow_threshold:
>>>>>>>>>>>>>>>>> 3.188464
>>>>>>>>>>>>>>>>> 90th_quantile_runtime: 0.459891
>>>>>>>>>>>>>>>>> that took a long time elapsed: 41.693553 slow_threshold:
>>>>>>>>>>>>>>>>> 3.183003
>>>>>>>>>>>>>>>>> 90th_quantile_runtime: 0.393654
>>>>>>>>>>>>>>>>> that took a long time elapsed: 39.679769 slow_threshold:
>>>>>>>>>>>>>>>>> 3.190782
>>>>>>>>>>>>>>>>> 90th_quantile_runtime: 0.393677
>>>>>>>>>>>>>>>>> that took a long time elapsed: 43.573411 slow_threshold:
>>>>>>>>>>>>>>>>> 3.239637
>>>>>>>>>>>>>>>>> 90th_quantile_runtime: 0.393654
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Code below
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> --------------------------------------------------------------
>>>>>>>>>>>>>>>>> import time
>>>>>>>>>>>>>>>>> from random import randint, choice
>>>>>>>>>>>>>>>>> import sys
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> allElems = {}
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> class Node:
>>>>>>>>>>>>>>>>> def __init__(self, v_):
>>>>>>>>>>>>>>>>> self.v = v_
>>>>>>>>>>>>>>>>> self.next = None
>>>>>>>>>>>>>>>>> self.dummy_data = [randint(0,100)
>>>>>>>>>>>>>>>>> for _ in xrange(randint(50,100))]
>>>>>>>>>>>>>>>>> allElems[self.v] = self
>>>>>>>>>>>>>>>>> if self.v > 0:
>>>>>>>>>>>>>>>>> self.dummy_links = [allElems[randint(0,
>>>>>>>>>>>>>>>>> self.v-1)]
>>>>>>>>>>>>>>>>> for _
>>>>>>>>>>>>>>>>> in
>>>>>>>>>>>>>>>>> xrange(10)]
>>>>>>>>>>>>>>>>> else:
>>>>>>>>>>>>>>>>> self.dummy_links = [self]
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> def set_next(self, l):
>>>>>>>>>>>>>>>>> self.next = l
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> def follow(node):
>>>>>>>>>>>>>>>>> acc = []
>>>>>>>>>>>>>>>>> count = 0
>>>>>>>>>>>>>>>>> cur = node
>>>>>>>>>>>>>>>>> assert node.v is not None
>>>>>>>>>>>>>>>>> assert cur is not None
>>>>>>>>>>>>>>>>> while count < 50000:
>>>>>>>>>>>>>>>>> # return a value; generate some garbage
>>>>>>>>>>>>>>>>> acc.append((cur.v,
>>>>>>>>>>>>>>>>> [choice("abcdefghijklmnopqrstuvwxyz")
>>>>>>>>>>>>>>>>> for
>>>>>>>>>>>>>>>>> x
>>>>>>>>>>>>>>>>> in
>>>>>>>>>>>>>>>>> xrange(100)]))
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> # if we have reached the end, chose a random link
>>>>>>>>>>>>>>>>> cur = choice(cur.dummy_links) if cur.next is None
>>>>>>>>>>>>>>>>> else
>>>>>>>>>>>>>>>>> cur.next
>>>>>>>>>>>>>>>>> count += 1
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> return acc
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> def build(num_elems):
>>>>>>>>>>>>>>>>> start = time.time()
>>>>>>>>>>>>>>>>> print "start build"
>>>>>>>>>>>>>>>>> root = Node(0)
>>>>>>>>>>>>>>>>> cur = root
>>>>>>>>>>>>>>>>> for x in xrange(1, num_elems):
>>>>>>>>>>>>>>>>> e = Node(x)
>>>>>>>>>>>>>>>>> cur.next = e
>>>>>>>>>>>>>>>>> cur = e
>>>>>>>>>>>>>>>>> print "end build %f" % (time.time() - start)
>>>>>>>>>>>>>>>>> return root
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> num_timings = 100
>>>>>>>>>>>>>>>>> if __name__ == "__main__":
>>>>>>>>>>>>>>>>> num_elems = int(sys.argv[1])
>>>>>>>>>>>>>>>>> build(num_elems)
>>>>>>>>>>>>>>>>> total = 0
>>>>>>>>>>>>>>>>> timings = [0.0] * num_timings # run times for the last
>>>>>>>>>>>>>>>>> num_timings
>>>>>>>>>>>>>>>>> runs
>>>>>>>>>>>>>>>>> i = 0
>>>>>>>>>>>>>>>>> beginning = time.time()
>>>>>>>>>>>>>>>>> while time.time() - beginning < 600:
>>>>>>>>>>>>>>>>> start = time.time()
>>>>>>>>>>>>>>>>> elem = allElems[randint(0, num_elems - 1)]
>>>>>>>>>>>>>>>>> assert(elem is not None)
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> lst = follow(elem)
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> total += choice(lst)[0] # use the return value for
>>>>>>>>>>>>>>>>> something
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> end = time.time()
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> elapsed = end-start
>>>>>>>>>>>>>>>>> timings[i % num_timings] = elapsed
>>>>>>>>>>>>>>>>> if (i > num_timings):
>>>>>>>>>>>>>>>>> slow_time = 2 * sum(timings)/num_timings # slow
>>>>>>>>>>>>>>>>> defined
>>>>>>>>>>>>>>>>> as
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> 2*avg run time
>>>>>>>>>>>>>>>>> if (elapsed > slow_time):
>>>>>>>>>>>>>>>>> print "that took a long time elapsed: %f
>>>>>>>>>>>>>>>>> slow_threshold:
>>>>>>>>>>>>>>>>> %f 90th_quantile_runtime: %f" % \
>>>>>>>>>>>>>>>>> (elapsed, slow_time,
>>>>>>>>>>>>>>>>> sorted(timings)[int(num_timings*.9)])
>>>>>>>>>>>>>>>>> i += 1
>>>>>>>>>>>>>>>>> print total
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> On Thu, Mar 13, 2014 at 7:45 PM, Maciej Fijalkowski
>>>>>>>>>>>>>>>>> <fijall at gmail.com>
>>>>>>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> On Thu, Mar 13, 2014 at 1:45 PM, Martin Koch
>>>>>>>>>>>>>>>>>> <mak at issuu.com>
>>>>>>>>>>>>>>>>>> wrote:
>>>>>>>>>>>>>>>>>>> Hi Armin, Maciej
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>> Thanks for responding.
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>> I'm in the process of trying to determine what (if any) of
>>>>>>>>>>>>>>>>>>> the
>>>>>>>>>>>>>>>>>>> code
>>>>>>>>>>>>>>>>>>> I'm
>>>>>>>>>>>>>>>>>>> in a
>>>>>>>>>>>>>>>>>>> position to share, and I'll get back to you.
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>> Allowing hinting to the GC would be good. Even better
>>>>>>>>>>>>>>>>>>> would be
>>>>>>>>>>>>>>>>>>> a
>>>>>>>>>>>>>>>>>>> means
>>>>>>>>>>>>>>>>>>> to
>>>>>>>>>>>>>>>>>>> allow me to (transparently) allocate objects in unmanaged
>>>>>>>>>>>>>>>>>>> memory,
>>>>>>>>>>>>>>>>>>> but I
>>>>>>>>>>>>>>>>>>> would expect that to be a tall order :)
>>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>>> Thanks,
>>>>>>>>>>>>>>>>>>> /Martin
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> Hi Martin.
>>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>> Note that in case you want us to do the work of isolating
>>>>>>>>>>>>>>>>>> the
>>>>>>>>>>>>>>>>>> problem,
>>>>>>>>>>>>>>>>>> we do offer paid support to do that (then we can sign NDAs
>>>>>>>>>>>>>>>>>> and
>>>>>>>>>>>>>>>>>> stuff).
>>>>>>>>>>>>>>>>>> Otherwise we would be more than happy to fix bugs once you
>>>>>>>>>>>>>>>>>> isolate
>>>>>>>>>>>>>>>>>> a
>>>>>>>>>>>>>>>>>> part you can share freely :)
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>
>>>>>>>
>>>>
>>>>
>>>
More information about the pypy-dev
mailing list