<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN">
<html>
<head>
  <meta content="text/html; charset=UTF-8" http-equiv="Content-Type">
</head>
<body bgcolor="#ffffff" text="#000000">
On 3/15/2012 1:09 AM, MinRK wrote:
<blockquote
 cite="mid:CAHNn8BVXn-sZtk-PyAY2a4gT7DQOWa2ya7BTN8XjNjw_S3LOtw@mail.gmail.com"
 type="cite">
  <pre wrap="">On Wed, Mar 14, 2012 at 08:22, RICHARD Georges-Emmanuel
<a class="moz-txt-link-rfc2396E" href="mailto:perspective.electronic@gmail.com">&lt;perspective.electronic@gmail.com&gt;</a> wrote:
  </pre>
  <blockquote type="cite">
    <pre wrap="">Hi all, Hi Minrk,

I'm not sure if I should post on IPython list or PyZMQ list,
    </pre>
  </blockquote>
  <pre wrap="">
IPython is the right place.

  </pre>
  <blockquote type="cite">
    <pre wrap="">
Brief: Usage of IPython parallel, I use DirectView object to "execute" code
on 32 engines and "pull" to retrieve results.
Those results are simply compared (means read only) to some range limit to
know which engine got error and which pass.
We repeat this, previous result are erase by new, so the memory footprint on
engines is constant.
from the IPython Client side, after a long run (it depends on user usage)
- currently it is not very intensive but as the system is never restarted
after several weeks it crashed,
- then it will be something like 1 execute every 1 or 3seconds followed by a
pull, I expect a crash within few days at this rhythm  :-( .
    </pre>
  </blockquote>
  <pre wrap="">
Wow, that's rough.  I hope we can figure this out.

  </pre>
  <blockquote type="cite">
    <pre wrap="">
TestCase:
-open a shell execute:
    ipcontroller --ip='*' --nodb
-then open another shell to start 32 engines,  I use python to do it:
import time,os
for i in range(32):
    os.popen("ipengine&amp;")
    time.sleep(1)
-execute the script (README_script_test.py attached to this mail):

When I started to debug and profile IPython internal method, I started to
insert some time.time() in each method involved in AsyncResult, finally I
pointed the client.py spin() method,
as I don't want you to modify your installation, in the script provided I
define a myClient class which inherit from IPython.parallel.Client and I
override spin method to add the time.time() that help me to figure out where
the time is spent.
Then it's a simple dview.execute to set a variable on all engines, followed
by a loop to retrieve the variable 1000 of times.
a boolean WRITECSVFILE, can be set to True to open profiling data in oocalc
or excel
a boolean TEST_MEMORY_ERROR, can be set to True, it just do more loops,
maybe need to be extended to reach the MemoryError but it's probably not
desired.


Issues:
1) with a result of type List, while I retrieve it a growing delay appear
every N ( 4 to 5 in case of 200 elements in list to pull with 32 engines, no
matters if elements are float only or string only or mixed)
AsyncResult.get().
    I did some profiling, this is what the test script help to produce, I
also modified client.py
    <a class="moz-txt-link-freetext" href="http://i40.tinypic.com/1z6bpuh.png">http://i40.tinypic.com/1z6bpuh.png</a>   or    <a class="moz-txt-link-freetext" href="http://dl.free.fr/bvYnPT3rR">http://dl.free.fr/bvYnPT3rR</a>

    I managed to notice spin() method of the client.py in which the
_flush_results(self._mux_socket) seems to be where the time is spent, but
then I do see the pyzmq interface involved but I don't understand what's
wrong with it.
    </pre>
  </blockquote>
  <pre wrap="">
I'll have to further investigate this one. I don't see anything
particularly strange in my running of the script.  Can you do some
profiling, to see what operations are actually taking the time?

  </pre>
</blockquote>
<br>
I profiled deeper in method _flush_results()  (the one that become
slower execution after execution of a pull('alistobject').r ),<br>
 and point the line: handler(msg)<br>
    def _flush_results(self, sock):<br>
        """Flush task or queue results waiting in ZMQ queue."""<br>
        idents,msg = self.session.recv(sock, mode=zmq.NOBLOCK)<br>
        while msg is not None:<br>
            if self.debug:<br>
                pprint(msg)<br>
            msg_type = msg['header']['msg_type']<br>
            handler = self._queue_handlers.get(msg_type, None)<br>
            if handler is None:<br>
                raise Exception("Unhandled message type:
%s"%msg.msg_type)<br>
            else:<br>
                handler(msg)    #######################################
Here is the incrinsing time, I continue to dig!<br>
            idents,msg = self.session.recv(sock, mode=zmq.NOBLOCK)<br>
<br>
Then I logged the 'msg' to stdout and pipe it to a file (something like
430MB of log), it tells me that 'msg_type' is 'apply_reply', all
'status' ar 'ok'.<br>
<br>
I profiled method _handle_apply_reply(),  and point the
util.unserialize_object()<br>
<br>
    def _handle_apply_reply(self, msg):<br>
        """Save the reply to an apply_request into our results."""<br>
        parent = msg['parent_header']<br>
        msg_id = parent['msg_id']<br>
        if msg_id not in self.outstanding:<br>
            if msg_id in self.history:<br>
                print ("got stale result: %s"%msg_id)<br>
                print self.results[msg_id]<br>
                print msg<br>
            else:<br>
                print ("got unknown result: %s"%msg_id)<br>
        else:<br>
            self.outstanding.remove(msg_id)<br>
        content = msg['content']<br>
        header = msg['header']<br>
<br>
        # construct metadata:<br>
        md = self.metadata[msg_id]<br>
        md.update(self._extract_metadata(header, parent, content))<br>
        # is this redundant?<br>
        self.metadata[msg_id] = md<br>
<br>
        e_outstanding = self._outstanding_dict[md['engine_uuid']]<br>
        if msg_id in e_outstanding:<br>
            e_outstanding.remove(msg_id)<br>
<br>
        # construct result:<br>
        if content['status'] == 'ok':<br>
            self.results[msg_id] =
util.unserialize_object(msg['buffers'])[0]  ################### Here we
are, this line is the one growing up in time.<br>
        elif content['status'] == 'aborted':<br>
            self.results[msg_id] = error.TaskAborted(msg_id)<br>
        elif content['status'] == 'resubmitted':<br>
            # TODO: handle resubmission<br>
            pass<br>
        else:<br>
            self.results[msg_id] = self._unwrap_exception(content)<br>
<br>
So I didn't feel hopeless, and I tried to understand where the time is
spent....<br>
def unserialize_object(bufs):<br>
    """reconstruct an object serialized by serialize_object from data
buffers."""<br>
    bufs = list(bufs)<br>
    sobj = pickle.loads(bufs.pop(0)) 
#################################### Here is the HOT line, <span
 class="moz-smiley-s15"><span> :'( </span></span><br>
    if isinstance(sobj, (list, tuple)):<br>
        for s in sobj:<br>
            if s.data is None:<br>
                s.data = bufs.pop(0)<br>
        return uncanSequence(map(unserialize, sobj)), bufs<br>
    elif isinstance(sobj, dict):<br>
        newobj = {}<br>
        for k in sorted(sobj.iterkeys()):<br>
            s = sobj[k]<br>
            if s.data is None:<br>
                s.data = bufs.pop(0)<br>
            newobj[k] = uncan(unserialize(s))<br>
        return newobj, bufs<br>
    else:<br>
        if sobj.data is None:<br>
            sobj.data = bufs.pop(0)<br>
        return uncan(unserialize(sobj)), bufs<br>
<br>
As I don't understand why this line    pickle.loads(bufs.pop(0))  get
slower and slower, after many execution, I decided to bench only
util.unserialize_object(),<br>
I copied only 1 'buffer' of a msg from the previous log, and
unserialize it 10000 times, absolutely no increase of time. Just work
as it should.<br>
<br>
So my only chance,  is to dig the log to find which 'buffer' make the
pickle.loads slow down.<br>
I did check the lenght of the bufs.pop(0), I splitted the line:<br>
tmp_pop = bufs.pop(0) # I checked len(tmp_pop), Ok, I am hopless.<br>
sobj = pickle.loads(tmp_pop)<br>
there is 30 first call with a buffer lenght of 115, then all other call
are with a buffer lenght of 6154.<br>
I am really confused, as I think pickle.loads is very stable, and I
cannot imagined a weird buffer can make it change behavior and slow
down.<br>
I may give a try to a 'msg' reader, to reinject the whole log I got, it
should make the issues appear, like it does with the Client.<br>
<br>
But I should maybe give a try with another python version first, like
2.7.<br>
<br>
<blockquote
 cite="mid:CAHNn8BVXn-sZtk-PyAY2a4gT7DQOWa2ya7BTN8XjNjw_S3LOtw@mail.gmail.com"
 type="cite">
  <pre wrap=""></pre>
  <blockquote type="cite">
    <pre wrap="">
2) memory usage keep growing, and finaly reach a MemoryError.
    no matter the type of data retrieved, numpy array, simple string, float
or a list.
    </pre>
  </blockquote>
  <pre wrap="">
This one's easy: <a class="moz-txt-link-freetext" href="https://github.com/ipython/ipython/issues/1131">https://github.com/ipython/ipython/issues/1131</a>

It's the very top of my IPython todo list, but getting it right in
general is a bit tricky with AsyncResults, etc., so I don't have an
implementation yet.  Maybe later today...

The Client caches all results in its `results` dictionary.  These are
not deduplicated with hashes or anything.  Just one object per Result
(note that each pull you are doing produces *32* results).  So by the
end of your script, you have at least 32000 copies of the list you are
pulling.

To clear this dictionary, simply call `client.results.clear()`.

For a full client-side purge:

# clear caches of results and metadata
client.results.clear()
client.metadata.clear()
view.results.clear()

# Also (optionally) clear the history of msg_ids
assert not client.outstanding, "don't clear when tasks are outstanding"
client.history = []
dview.history = []

Using this, I have run large amounts data-moving tasks (1 MB/s on
average) for a couple of days (totaling 100s of GB) without
encountering memory issues.

  </pre>
</blockquote>
<br>
Good news, I didn't give a try yet for this, that's my next step.<br>
<br>
<blockquote
 cite="mid:CAHNn8BVXn-sZtk-PyAY2a4gT7DQOWa2ya7BTN8XjNjw_S3LOtw@mail.gmail.com"
 type="cite">
  <pre wrap=""></pre>
  <blockquote type="cite">
    <pre wrap="">
 comments:
       concerning 1)  I understand the serialization following the type of
results, it takes more or less time to retrieve, BUT if the time is rising
pull after pull on the same result (it seems to be only with List) something
else is involved, and I don't catch it.
       concerning 2)  I though the Hub Database could have been involved, so
when I start the ipcontroller I added --nodb, but I still got the
MemoryError, moreover this option concerns only the ipcontroller app,

also I tried    rc.purge_results('all'), but didn't see any impact.
    </pre>
  </blockquote>
  <pre wrap="">
purge_results is strictly a Hub DB operation.  Working out exactly how

  </pre>
  <blockquote type="cite">
    <pre wrap="">are    rc.history,    dview.results,    rc.session.digest_history or other
internal object should be cleared regularly?

I read this:

<a class="moz-txt-link-freetext" href="http://ipython.org/ipython-doc/stable/parallel/parallel_details.html#non-copying-sends-and-numpy-arrays">http://ipython.org/ipython-doc/stable/parallel/parallel_details.html#non-copying-sends-and-numpy-arrays</a>

What is sendable (...)

(unless the data is very small)      -----&gt; I'am not sure what that means,
but if a results is pulled twice, how to do to make the 2nd erase the 1st
one.


Question:
any kind people who want give a try to the script I attached to confirm the
behaviour, any hint to avoid my IPython client process to slow down, and
reach a MemoryError, or do I miss a page in the manual about clear the
memory in the user application?
    </pre>
  </blockquote>
  <pre wrap="">
This should certainly be in the docs, but it probably hasn't been
because I have considered it a bug I should fix, rather than behavior
to be documented.

-MinRK
  </pre>
</blockquote>
<br>
Great work, that's on the good way, another thumb up for the notebook.<br>
<br>
<br>
<blockquote
 cite="mid:CAHNn8BVXn-sZtk-PyAY2a4gT7DQOWa2ya7BTN8XjNjw_S3LOtw@mail.gmail.com"
 type="cite">
  <pre wrap=""></pre>
  <blockquote type="cite">
    <pre wrap="">in advance Thanks, keep the good works!

Environment:
Linux RHEL 5.5, python 2.6.6
ipython 0.12, then upgrade to the latest git 0.13dev
zmq+pyzmq 2.1.7, then upgrade to the latest zmq+pyzmq 2.1.11
jsonlib2     1.3.10

Cheers,
       Joe

--
RICHARD Georges-Emmanuel


_______________________________________________
IPython-User mailing list
<a class="moz-txt-link-abbreviated" href="mailto:IPython-User@scipy.org">IPython-User@scipy.org</a>
<a class="moz-txt-link-freetext" href="http://mail.scipy.org/mailman/listinfo/ipython-user">http://mail.scipy.org/mailman/listinfo/ipython-user</a>

    </pre>
  </blockquote>
  <pre wrap="">_______________________________________________
IPython-User mailing list
<a class="moz-txt-link-abbreviated" href="mailto:IPython-User@scipy.org">IPython-User@scipy.org</a>
<a class="moz-txt-link-freetext" href="http://mail.scipy.org/mailman/listinfo/ipython-user">http://mail.scipy.org/mailman/listinfo/ipython-user</a>
  </pre>
</blockquote>
<br>
<br>
<div class="moz-signature">-- <br>
<a href="skype:joe_aie?call"><img
 src="cid:part1.06040806.07010706@aie-etudes.com"
 style="border: medium none ;" alt="Skype Me™!" height="52" width="124"></a><br>
<a href="http://www.skype.com/go/download">Get Skype</a> and call me
for free.<br>
<br>
</div>
</body>
</html>