Page MenuHomePhabricator

parliamentdiagram tool webservice repeatedly stopping
Open, Needs TriagePublic

Description

The tool parliamentdiagram on the tool server has been going down without being restarted since late December 2019.

Recent extracts from /data/project/parliamentdiagram/error.log have been pasted at https://wikitech.wikimedia.org/wiki/User:Slashme/logpaste

Event Timeline

10:18:08 0 ✓ zhuyifei1999@tools-sgebastion-09: ~$ grep parliamentdiagram /data/project/.system_sge/gridengine/default/common/accounting
task:tools-sgeexec-0933.tools.eqiad.wmflabs:tools.parliamentdiagram:tools.parliamentdiagram:cron-tools.parliamentdiagram-1:143498:sge:0:1580021582:1580021592:1580021593:0:0:1:0.004000:0.012000:3852.000000:0:0:0:0:983:0:0:8.000000:8:0:0:0:457:10:NONE:defaultdepartment:NONE:1:0:0.016000:0.000000:0.000000:-q task -l h_vmem=524288k:0.000000:NONE:0.000000:0:0
[...]
webgrid-lighttpd:tools-sgewebgrid-lighttpd-0916.tools.eqiad.wmflabs:tools.parliamentdiagram:tools.parliamentdiagram:lighttpd-parliamentdiagram:460252:sge:0:1579694757:1579694764:1580077607:37:0:382843:0.016000:0.004000:6456.000000:0:0:0:0:857:28:0:6280.000000:0:0:0:0:72:9:NONE:defaultdepartment:NONE:1:0:191.790000:72.662859:9.654144:-q webgrid-lighttpd -l h_vmem=4G:0.000000:NONE:4779155456.000000:0:0
[...]
webgrid-lighttpd:tools-sgewebgrid-lighttpd-0912.tools.eqiad.wmflabs:tools.parliamentdiagram:tools.parliamentdiagram:lighttpd-parliamentdiagram:237421:sge:0:1580161168:1580161182:1580401877:37:0:240695:0.020000:0.004000:6348.000000:0:0:0:0:863:2:0:24.000000:8:0:0:0:10:8:NONE:defaultdepartment:NONE:1:0:1641.300000:34.918114:4.651640:-q webgrid-lighttpd -l h_vmem=4G:0.000000:NONE:4420464640.000000:0:0
[...]
webgrid-lighttpd:tools-sgewebgrid-lighttpd-0922.tools.eqiad.wmflabs:tools.parliamentdiagram:tools.parliamentdiagram:lighttpd-parliamentdiagram:391323:sge:0:1580412371:1580412372:1580474692:37:0:62320:0.068000:0.036000:6216.000000:0:0:0:0:820:0:0:0.000000:0:0:0:0:9:15:NONE:defaultdepartment:NONE:1:0:239.950000:233.663917:0.889195:-q webgrid-lighttpd -l h_vmem=4G:0.000000:NONE:4334555136.000000:0:0
[...]

Checking last entry, adapting code from https://phabricator.wikimedia.org/source/tool-grid-jobs/browse/master/grid_jobs/__init__.py$27:

10:22:53 0 ✓ zhuyifei1999@tools-sgebastion-08: ~$ python
Python 2.7.13 (default, Sep 26 2018, 18:42:22) 
[GCC 6.3.0 20170516] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> ACCOUNTING_FIELDS = [
...     'qname', 'hostname', 'group', 'owner', 'job_name', 'job_number',
...     'account', 'priority', 'submission_time', 'start_time', 'end_time',
...     'failed', 'exit_status', 'ru_wallclock', 'ru_utime', 'ru_stime',
...     'ru_maxrss', 'ru_ixrss', 'ru_ismrss', 'ru_idrss', 'ru_isrss', 'ru_minflt',
...     'ru_majflt', 'ru_nswap', 'ru_inblock', 'ru_oublock', 'ru_msgsnd',
...     'ru_msgrcv', 'ru_nsignals', 'ru_nvcsw', 'ru_nivcsw', 'project',
...     'department', 'granted_pe', 'slots', 'task_number', 'cpu', 'mem', 'io',
...     'category', 'iow', 'pe_taskid', 'maxvemem', 'arid', 'ar_submission_time',
... ]
>>> line = 'webgrid-lighttpd:tools-sgewebgrid-lighttpd-0922.tools.eqiad.wmflabs:tools.parliamentdiagram:tools.parliamentdiagram:lighttpd-parliamentdiagram:391323:sge:0:1580412371:1580412372:1580474692:37:0:62320:0.068000:0.036000:6216.000000:0:0:0:0:820:0:0:0.000000:0:0:0:0:9:15:NONE:defaultdepartment:NONE:1:0:239.950000:233.663917:0.889195:-q webgrid-lighttpd -l h_vmem=4G:0.000000:NONE:4334555136.000000:0:0'
>>> __import__('pprint').pprint(dict(zip(ACCOUNTING_FIELDS, line.split(':'))))
{'account': 'sge',
 'ar_submission_time': '0',
 'arid': '0',
 'category': '-q webgrid-lighttpd -l h_vmem=4G',
 'cpu': '239.950000',
 'department': 'defaultdepartment',
 'end_time': '1580474692',
 'exit_status': '0',
 'failed': '37',
 'granted_pe': 'NONE',
 'group': 'tools.parliamentdiagram',
 'hostname': 'tools-sgewebgrid-lighttpd-0922.tools.eqiad.wmflabs',
 'io': '0.889195',
 'iow': '0.000000',
 'job_name': 'lighttpd-parliamentdiagram',
 'job_number': '391323',
 'maxvemem': '4334555136.000000',
 'mem': '233.663917',
 'owner': 'tools.parliamentdiagram',
 'pe_taskid': 'NONE',
 'priority': '0',
 'project': 'NONE',
 'qname': 'webgrid-lighttpd',
 'ru_idrss': '0',
 'ru_inblock': '0.000000',
 'ru_ismrss': '0',
 'ru_isrss': '0',
 'ru_ixrss': '0',
 'ru_majflt': '0',
 'ru_maxrss': '6216.000000',
 'ru_minflt': '820',
 'ru_msgrcv': '0',
 'ru_msgsnd': '0',
 'ru_nivcsw': '15',
 'ru_nsignals': '0',
 'ru_nswap': '0',
 'ru_nvcsw': '9',
 'ru_oublock': '0',
 'ru_stime': '0.036000',
 'ru_utime': '0.068000',
 'ru_wallclock': '62320',
 'slots': '1',
 'start_time': '1580412372',
 'submission_time': '1580412371',
 'task_number': '0'}

sge_status(5): failed status 37 means qmaster enforced h_rt, h_cpu, or h_vmem limit

maxvemem is above 4GiB and h_vmem=4G, so yes, this is killed by VMS limit exceeded. Are you mapping files into memory?

for x in range(sumdelegates['head']):
    poslist['head'].append(
        [5.0+blocksize*(x+optionlist['spacing']/2), centertop])
# Cross-bench parties are 5 from the edge, vertically centered:
for x in range(optionlist['centercols']):
    # How many rows in this column of the cross-bench
    thiscol = int(min(centerrows, sumdelegates['center']-x*centerrows))
    for y in range(thiscol):
        poslist['center'].append([svgwidth-5.0-(optionlist['centercols']-x-optionlist['spacing']/2)
                                  * blocksize, ((svgheight-thiscol*blocksize)/2)+blocksize*(y+optionlist['spacing']/2)])
        poslist['center'].sort(key=lambda point: point[1])
# Left parties are in the top block:
for x in range(wingcols):
    for y in range(optionlist['wingrows']['left']):
        poslist['left'].append(
            [5+(leftoffset+x+optionlist['spacing']/2)*blocksize, centertop-(1.5+y)*blocksize])
# Right parties are in the bottom block:
for x in range(wingcols):
    for y in range(optionlist['wingrows']['right']):
        poslist['right'].append(
            [5+(leftoffset+x+optionlist['spacing']/2)*blocksize, centertop+(1.5+y)*blocksize])

I can imagine these appends being really expensive.

An integer in python2 would be at least 24 bytes:

>>> sys.getsizeof(1)
24

You wrap it in a list of 2 elements, 88 bytes:

>>> sys.getsizeof([1,1])
88

And you append the element, 8 bytes:

>>> sys.getsizeof([1]) - sys.getsizeof([])
8

So 2 integers + a list of two elements + 1 entry in a preexisting list = 144 bytes per append. Multiply that by the number of appends, you have a lower bound on the memory consumption. I bet it's huge.

Thank you! I'll find a leaner way to do this :-D

OK, now I have my doubts that this is the issue: to try to reproduce the issue, I made some diagrams so large that they take a minute to render on my browser, with hundreds of thousands of delegates, and nothing breaks. I did a quick calculation, and for the largest parliament in the world, the PRC, with almost 3000 members, we'd have on the order of 432k.

What's the best way for me to find out how much memory my code is using?

This comment was removed by Slashme.

I can do some profiling. Do you have the data that is passed into the service right before it fails?

Looking at:

10:17:15 0 ✓ zhuyifei1999@tools-sgewebgrid-lighttpd-0919: ~$ ps uf -u tools.parliamentdiagram
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
tools.p+  8870  0.0  0.0  62036  6888 ?        Ss   Jan31   0:55 /usr/sbin/lighttpd -f /var/run/lighttpd/parliamentdiagram -D
tools.p+  8874  0.0  0.4 525748 34200 ?        Ss   Jan31   0:00  \_ /usr/bin/php-cgi
tools.p+  8875  0.0  0.2 526244 16692 ?        S    Jan31   0:00  |   \_ /usr/bin/php-cgi
tools.p+  8876  0.0  0.2 526244 16648 ?        S    Jan31   0:00  |   \_ /usr/bin/php-cgi
tools.p+  8877  0.0  0.4 525748 34328 ?        Ss   Jan31   0:00  \_ /usr/bin/php-cgi
tools.p+ 19347  0.0  0.3 600292 25488 ?        S    Feb01   0:01      \_ /usr/bin/php-cgi
tools.p+ 19807  0.0  0.3 600292 25484 ?        S    Feb01   0:01      \_ /usr/bin/php-cgi
10:18:33 0 ✓ zhuyifei1999@tools-sgewebgrid-lighttpd-0919: ~$ cat /proc/8870/limits 
Limit                     Soft Limit           Hard Limit           Units     
Max cpu time              unlimited            unlimited            seconds   
Max file size             unlimited            unlimited            bytes     
Max data size             unlimited            unlimited            bytes     
Max stack size            unlimited            unlimited            bytes     
Max core file size        unlimited            unlimited            bytes     
Max resident set          unlimited            unlimited            bytes     
Max processes             31859                31859                processes 
Max open files            1024                 4096                 files     
Max locked memory         65536                65536                bytes     
Max address space         4294967296           4294967296           bytes     
Max file locks            unlimited            unlimited            locks     
Max pending signals       31859                31859                signals   
Max msgqueue size         819200               819200               bytes     
Max nice priority         0                    0                    
Max realtime priority     0                    0                    
Max realtime timeout      unlimited            unlimited            us

That's RLIMIT_AS at 4GiB. rlimit is super confusing, and if I understand correctly, the 6 PHP processes would have already taken 3GiB of VMS (virtual memory size (VSZ = virtual size), also called address space (that's the AS in RLIMIT_AS)), leaving less than 1GiB VMS for other CGI scripts to play around in.

Though, if you want a much saner calculation of memory size, try k8s. It uses cgroups to limit RSS (resident set size, the amount of memory that is resident on the RAM chips), rather than this mad use of rlimit to limit VMS.

That said, if you want, I can do profiling and check what part of code is using up all the memory.

Thank you very much! I'm leaving on a week-long business trip this morning,
so I'll see when I can snatch some time to investigate. Will reply on
phabricator as soon as I have taken a proper look.

zhuyifei1999 <no-reply@phabricator.wikimedia.org> schrieb am So., 2. Feb.
2020, 23:30:

zhuyifei1999 added a comment. View Task
https://phabricator.wikimedia.org/T244036

Looking at:

10:17:15 0 ✓ zhuyifei1999@tools-sgewebgrid-lighttpd-0919: ~$ ps uf -u tools.parliamentdiagram
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
tools.p+ 8870 0.0 0.0 62036 6888 ? Ss Jan31 0:55 /usr/sbin/lighttpd -f /var/run/lighttpd/parliamentdiagram -D
tools.p+ 8874 0.0 0.4 525748 34200 ? Ss Jan31 0:00 \_ /usr/bin/php-cgi
tools.p+ 8875 0.0 0.2 526244 16692 ? S Jan31 0:00 | \_ /usr/bin/php-cgi
tools.p+ 8876 0.0 0.2 526244 16648 ? S Jan31 0:00 | \_ /usr/bin/php-cgi
tools.p+ 8877 0.0 0.4 525748 34328 ? Ss Jan31 0:00 \_ /usr/bin/php-cgi
tools.p+ 19347 0.0 0.3 600292 25488 ? S Feb01 0:01 \_ /usr/bin/php-cgi
tools.p+ 19807 0.0 0.3 600292 25484 ? S Feb01 0:01 \_ /usr/bin/php-cgi
10:18:33 0 ✓ zhuyifei1999@tools-sgewebgrid-lighttpd-0919: ~$ cat /proc/8870/limits
Limit Soft Limit Hard Limit Units
Max cpu time unlimited unlimited seconds
Max file size unlimited unlimited bytes
Max data size unlimited unlimited bytes
Max stack size unlimited unlimited bytes
Max core file size unlimited unlimited bytes
Max resident set unlimited unlimited bytes
Max processes 31859 31859 processes
Max open files 1024 4096 files
Max locked memory 65536 65536 bytes
Max address space 4294967296 4294967296 bytes
Max file locks unlimited unlimited locks
Max pending signals 31859 31859 signals
Max msgqueue size 819200 819200 bytes
Max nice priority 0 0
Max realtime priority 0 0
Max realtime timeout unlimited unlimited us

That's RLIMIT_AS at 4GiB. rlimit is super confusing
https://danielzhou82.github.io/blog/2014/09/30/on-the-confusing-ulimit/,
and if I understand correctly, the 6 PHP processes would have already taken
3GiB of VMS (virtual memory size (VSZ = virtual size), also called address
space (that's the AS in RLIMIT_AS)), leaving less than 1GiB VMS for other
CGI scripts to play around in.

Though, if you want a much saner calculation of memory size, try k8s. It
uses cgroups to limit RSS (resident set size, the amount of memory that is
resident on the RAM chips), rather than this mad use of rlimit to limit VMS.

That said, if you want, I can do profiling and check what part of code is
using up all the memory.

*TASK DETAIL*
https://phabricator.wikimedia.org/T244036

*EMAIL PREFERENCES*
https://phabricator.wikimedia.org/settings/panel/emailpreferences/

*To: *Slashme, zhuyifei1999
*Cc: *zhuyifei1999, Aklapper, Slashme, Zylc, 1978Gage2001, DSquirrelGM,
Jayprakash12345, Chicocvenancio, Tbscho, JJMC89, Jitrixis, Gryllida, scfc,
Mbch331, Krenair

@Slashme: Hi! Any news to share? Asking as you're set as task assignee. Thanks!

The problem seems to have gone away by itself! I guess the task can be closed.

Removing task assignee due to inactivity, as this open task has been assigned for more than two years. See the email sent to the task assignee on February 06th 2022 (and T295729).

Please assign this task to yourself again if you still realistically [plan to] work on this task - it would be welcome.

If this task has been resolved in the meantime, or should not be worked on ("declined"), please update its task status via "Add Action… 🡒 Change Status".

Also see https://www.mediawiki.org/wiki/Bug_management/Assignee_cleanup for tips how to best manage your individual work in Phabricator.