[netsa-tools-discuss] Any known issues with memory use and python plugins?

Mon Feb 19 11:28:29 EST 2018

Matt-

Writing a C plug-in is documented in the silk-plugin(3) man page.

http://tools.netsa.cert.org/silk/silk-plugin.html

-Mark

-----Original Message-----
From: "Markland, Matthew W. (Matt), M.S." <Markland.Matthew at mayo.edu>
Date: Mon, 19 Feb 2018 14:12:33 +0000
To: Mark Thomas <mthomas at cert.org>
Cc: "netsa-tools-discuss at cert.org" <netsa-tools-discuss at cert.org>
Subject: Re: [netsa-tools-discuss] Any known issues with memory use and python plugins?

Mark:

Excellent news! Thank you so much for your quick response.

I will have to look into those memory usage tools and get a better
feel for things on the python side. One workaround I've been thinking
about is writing a C plugin instead, based on the plugins that are
shipped with SiLK. In my skimming of the documentation I didn't see
any explicit discussion of the process for writing a plugin in C; is
this a supported use case for end users? I've been a little frantic,
so I could easily have missed the spot in the docs where it discusses
how to do it.

Thanks again for all the support. 

Matt
-- 
Matthew Markland | Sr Analyst/Programmer | Information Technology | 507-538-5493 | markland.matthew at mayo.edu
Mayo Clinic | 200 First Street SW | Rochester, MN 55905 | www.mayoclinic.org

On 2/16/18, 5:16 PM, "Mark Thomas" <mthomas at cert.org> wrote:

    Matt-

    I found the bug and have fixed it in the SiLK 3.16.1 Release that
    is now available.

    As far as Python memory usage goes, recent releases of Python have
    increased the memory debugging tools available:

    * Python 3.4 added the tracemalloc module.
      https://docs.python.org/3/library/tracemalloc.html

    * Python 3.6 allow run-time selection of Python's internal allocator
      via the PYTHONMALLOC environment variable, and PYTHONMALLOCSTATS
      now works in release mode.

    The tracemalloc module shows the size before any data was processed
    at 3,770,209 bytes.  After processing 15.7 million records, the size
    was 3,779,599 bytes.

    My simple script is attached.

    -Mark

    -----Original Message-----
    From: "Markland, Matthew W. (Matt), M.S." <Markland.Matthew at mayo.edu>
    Date: Tue, 13 Feb 2018 18:12:49 +0000
    To: Mark Thomas <mthomas at cert.org>
    Cc: "netsa-tools-discuss at cert.org" <netsa-tools-discuss at cert.org>
    Subject: Re: [netsa-tools-discuss] Any known issues with memory use and python
     plugins?

    Mark:

    Thank you for the feedback. The larger buffer sizes make sense re:
    memory usage. I knew that had come in but had trouble isolating when
    in the release notes. I probably just rushed over it in my
    reviews. I'm going to take a closer look at those environment
    variables and do some tests to see if we can get similar output to our
    previous runs without too much performance loss.

    Before I leave the memory usage topic I did want to bring up one other
    behavior I've noticed. In my rwuniq runs so far memory use seems to
    double when running with our python plugin versus without. Do you have
    a feel for what sort of overhead the use of the python plugins adds in
    general and if there are ways to reduce memory usage in that model?
    I'll be digging in the documentation for this, but any hints you have
    would be welcomed.

    Matt
    -- 
    Matthew Markland | Sr Analyst/Programmer | Information Technology | 507-538-5493 | markland.matthew at mayo.edu
    Mayo Clinic | 200 First Street SW | Rochester, MN 55905 | www.mayoclinic.org

    On 2/9/18, 4:57 PM, "Mark Thomas" <mthomas at cert.org> wrote:

        Matt-

        One explanation for the larger memory numbers in SiLK 3.16 is that
        our hash table no-longer limits itself to 2GB of RAM on 64-bit
        systems.  That change was introduced in SiLK 3.14.

        Prior to 3.14.0, rwuniq (and rwstats) made use of temporary files
        when the hash table's size approached 2GB.  The tools are still
        capable or using temporary files, but they need to do so less often
        because of the larger memory limit.

        However, that does not explain why your output is malformed.  I will
        investigate and see what I can determine.

        In the meantime, here are two environment variables that may help
        you in debugging this issue.  Setting the second one to "4g" should
        cause rwuniq to behave as it did in SiLK 3.11.

        * SILK_UNIQUE_DEBUG

          When set to 1, the binning engine used by rwuniq prints debugging
          messages to the standard error.  These messages are mostly about
          writing, reading, and merging temporary files.

        * SILK_HASH_MAXMEM

          Specifies the maximum number of bytes in memory a hash table may
          occupy.  This accepts the same sort of argument as the
          --sort-buffer-size switch from rwsort; that is, you may append k,
          m, g, for kilo-, mega-, giga-bytes, respectively.

        Cheers,

        -Mark

        -----Original Message-----
        From: "Markland, Matthew W. (Matt), M.S." <Markland.Matthew at mayo.edu>
        Date: Wed, 7 Feb 2018 21:53:23 +0000
        To: "netsa-tools-discuss at cert.org" <netsa-tools-discuss at cert.org>
        Subject: [netsa-tools-discuss] Any known issues with memory use and python
        	plugins?

        All:

        I'm working on moving a workflow from SiLK 3.11.0.1 to SiLK 3.16 and
        have run into some interesting memory usage numbers. I have a large
        deduped file (1.6Gb compressed) which I'm running rwuniq on with a
        custom python plugin which adds two fields to the output. The python
        plugin is not doing any real computation per se (i.e. no heavy
        math). What caused me to notice something was up is that the output
        from rwuniq when using SiLK 3.16 has entries in it which have
        addresses not in the dedupe file and the entries also appear
        malformed.

        A typical invocation of rwuniq looks like. 

        /usr/bin/time /home/users/software/silk/bin/rwuniq
        --python-file=../scripts/get_mseconds.py
        --values=Records,Packets,Bytes,start_mseconds,end_mseconds
        --fields=1-5,8 --timestamp-format=iso,local --ipv6-policy=asv4
        --delimited=, 2018020214.dedupe > 2018020214.summary

        I'm running on a 16-core machine with plenty of RAM. When I run I see
        the following "Max Resident Memory" numbers as provided by
        /usr/bin/time:

        3.11.0.1:  842700
        3.16:         5577576 

        Seeing this I'm guessing the mangled output is due to hitting some sort of 4Gb limit. If I don't use the python plugin I see this 

        3.16:  2787624

        Which still doesn't seem to be stellar in my mind, but at least it doesn't mangle the output.

        Looking at the config.log file for the 3.16 build I don't see anything
        that would appear to change its behavior like this. It was built with
        gcc 4.8.5 on CentOS (I believe).

        I'm thinking that I may not need the python plugin going forward (more
        experiments to run), but I wanted to see if anyone else has seen
        memory usage like this.

        Thanks for your time!

        Matt

        -- 
        Matthew Markland | Sr Analyst/Programmer | Information Technology | 507-538-5493 | markland.matthew at mayo.edu
        Mayo Clinic | 200 First Street SW | Rochester, MN 55905 | www.mayoclinic.org