Rocksolid Light

Welcome to novaBBS (click a section below)

mail  files  register  newsreader  groups  login

Message-ID:  

<<<<< EVACUATION ROUTE <<<<<

devel / comp.lang.python / Performance issue with CPython 3.10 + Cython

SubjectAuthor
o Performance issue with CPython 3.10 + CythonAndreas Ames

1
Performance issue with CPython 3.10 + Cython

<mailman.522.1664893068.20444.python-list@python.org>

  copy mid

https://www.novabbs.com/devel/article-flat.php?id=19649&group=comp.lang.python#19649

  copy link   Newsgroups: comp.lang.python
Path: i2pn2.org!i2pn.org!news.swapon.de!fu-berlin.de!uni-berlin.de!not-for-mail
From: andreas....@gmail.com (Andreas Ames)
Newsgroups: comp.lang.python
Subject: Performance issue with CPython 3.10 + Cython
Date: Tue, 4 Oct 2022 11:05:42 +0200
Lines: 127
Message-ID: <mailman.522.1664893068.20444.python-list@python.org>
References: <CAHAfzDke_yStz-M-m6yTLx7E=ZDserw7O8AP81xVdmje6yvi0g@mail.gmail.com>
Mime-Version: 1.0
Content-Type: text/plain; charset="UTF-8"
X-Trace: news.uni-berlin.de zSkLl2CSefYXI7C8NfHp9wYT4SQnjCC8cbLA/pwRIYHQ==
Return-Path: <andreas.0815.qwertz@gmail.com>
X-Original-To: python-list@python.org
Delivered-To: python-list@mail.python.org
Authentication-Results: mail.python.org; dkim=pass
reason="2048-bit key; unprotected key"
header.d=gmail.com header.i=@gmail.com header.b=XR1bZQ49;
dkim-adsp=pass; dkim-atps=neutral
X-Spam-Status: OK 0.051
X-Spam-Evidence: '*H*': 0.90; '*S*': 0.00; '700': 0.04; 'loop': 0.07;
'1600': 0.09; '900': 0.09; 'utility': 0.09; 'log': 0.12; 'memory':
0.15; '1100': 0.16; '1400': 0.16; '1700': 0.16; '2400': 0.16;
'apis,': 0.16; 'code.\xc2\xa0': 0.16; 'consume': 0.16;
'corresponds': 0.16; 'cpython.': 0.16; 'cython,': 0.16;
'decreases': 0.16; 'extending': 0.16; 'functions,': 0.16;
'functions.': 0.16; 'me.\xc2\xa0': 0.16; 'subject:3.10': 0.16;
'subject:CPython': 0.16; 'subject:Cython': 0.16; 'subject:issue':
0.16; 'time",': 0.16; 'whatsoever.': 0.16; 'python': 0.16; 'api':
0.17; 'code.': 0.17; 'uses': 0.19; 'calls': 0.19; 'to:addr:python-
list': 0.20; 'all,': 0.20; 'application.': 0.22; 'i.e.': 0.22;
'code': 0.23; 'done': 0.28; 'output': 0.28; 'series': 0.28;
'ideas': 0.28; 'suggest': 0.28; 'seem': 0.31; 'effect': 0.31;
'execution': 0.32; 'message-id:@mail.gmail.com': 0.32; 'but':
0.32; 'there': 0.33; '100': 0.33; 'same': 0.34;
'received:google.com': 0.34; 'from:addr:gmail.com': 0.35;
'functions': 0.36; 'those': 0.36; 'using': 0.37;
'received:209.85': 0.37; 'could': 0.38; 'thanks': 0.38;
'received:209': 0.39; 'use': 0.39; 'still': 0.40; 'design,': 0.40;
'done.': 0.40; 'experiences': 0.40; 'seconds': 0.40; 'counts':
0.60; 'numerous': 0.60; 'physical': 0.60; 'skip:0 20': 0.61;
'me.': 0.62; 'here': 0.62; 'everything': 0.63; '200': 0.65;
'look': 0.65; 'less': 0.65; 'time.': 0.66; 'now,': 0.67; 'time,':
0.67; 'per': 0.68; 'right': 0.68; 'exactly': 0.68; 'during': 0.69;
'600': 0.69; '1000': 0.70; '500': 0.70; 'performance': 0.71;
'experts': 0.76; '400': 0.78; 'happens': 0.84; '2500': 0.84;
'2600': 0.84; '2800': 0.84; 'cycle': 0.84; 'domains.': 0.84;
'executing': 0.84; 'executive,': 0.84; 'observing': 0.84;
'subject:Performance': 0.84; 'those,': 0.84; 'time).': 0.84
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20210112;
h=to:subject:message-id:date:from:mime-version:from:to:cc:subject
:date; bh=FdNwHN6jdMcrLd9ierWR60+ldtI87NClc5Rip7vve+U=;
b=XR1bZQ49CnQUsYbm/EjsbnS9696Lc9ayKTF8pYDy50sdMM8KrRrQdgR9UKENqYkUrP
sEYWmSBTt3Nq5VnZCYtO/4W8Z5qGkmolP4zSo6FNHdxtuT/1D8MIV3l/eH8rqvpdi94d
p2HStaaraF1c73lJnufBDEluYupgFEGJ/fr55YYRh9wx2jd126NQvdwfCKxG6tl3NxJ6
ggajaofAbBT7bXSMFr+l7rVUVwqHPQq7on3s0hPtF+wqMSlwjD8TYdXghSSSPMolzO7x
R9nQHpyq1OWCIn1uYJlkK7p/oU5cMfjukWEOHvdihFrmpGKERqupYX/0zOkk3GXIKdN+
1XPg==
X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed;
d=1e100.net; s=20210112;
h=to:subject:message-id:date:from:mime-version:x-gm-message-state
:from:to:cc:subject:date;
bh=FdNwHN6jdMcrLd9ierWR60+ldtI87NClc5Rip7vve+U=;
b=YioaYoqKPUQeddh5ePgoaKJfSr2dC0SUDTjBMxldhmDppVLJJlD/UH2KnnbfA6N2Gp
Kzz/t/TOar9Eg7qjNDsywrfKhNL/6oWzQAIQAwUpyoR4+2SPUV0hAL6K3p8S8LK9Y3Mu
Sbj9/9bDIbJ8VFybDn4nYUv6ojoVnhrX8teX+Bv21fMWg4CCXiD6JCizBVp6TMrVBYvU
Wp1hLAgpjQUMb69Aa5cRk5JGKr9dz5a0pN4uAo3CJTi7HJFR1NbVLeb0W0PMIIMZblz/
gdcycrVLdvGt34GFFRNkA2udLSl6+ON1N10y8TWecTPDHWFGnP0e28oS9T74m7sinNyi
sW2A==
X-Gm-Message-State: ACrzQf0N3NoZSam6DbYRIZuN33TWxhbZ8xRRk1ih5Tcg/w1C0O0oDTsd
yPRYowifnud4/H3NtxE/fMUULta22k2VsA8FaFRIrAPLthc=
X-Google-Smtp-Source: AMsMyM6UxstvTa459o2G0p+OmwnfYnVTV9cYPzUSaN7HowsXAui2lZm7Bj8TPiC78QbzcLtgUqRZSVZ+JRzlvsaEZJc=
X-Received: by 2002:a81:8c6:0:b0:354:d367:a807 with SMTP id
189-20020a8108c6000000b00354d367a807mr23490247ywi.272.1664874353828; Tue, 04
Oct 2022 02:05:53 -0700 (PDT)
X-Mailman-Approved-At: Tue, 04 Oct 2022 10:17:47 -0400
X-Content-Filtered-By: Mailman/MimeDel 2.1.39
X-BeenThere: python-list@python.org
X-Mailman-Version: 2.1.39
Precedence: list
List-Id: General discussion list for the Python programming language
<python-list.python.org>
List-Unsubscribe: <https://mail.python.org/mailman/options/python-list>,
<mailto:python-list-request@python.org?subject=unsubscribe>
List-Archive: <https://mail.python.org/pipermail/python-list/>
List-Post: <mailto:python-list@python.org>
List-Help: <mailto:python-list-request@python.org?subject=help>
List-Subscribe: <https://mail.python.org/mailman/listinfo/python-list>,
<mailto:python-list-request@python.org?subject=subscribe>
X-Mailman-Original-Message-ID: <CAHAfzDke_yStz-M-m6yTLx7E=ZDserw7O8AP81xVdmje6yvi0g@mail.gmail.com>
 by: Andreas Ames - Tue, 4 Oct 2022 09:05 UTC

Hi all,

I am wrapping an embedded application (, which does not use any dynamic
memory management,) using Cython to call it from CPython. The wrapped
application uses a cyclic executive, i.e. everything is done in the
input-logic-output design, typical for some real-time related domains.
Consequentially, every application cycle executes more or less the very
same code. As I am still in a prototyping stadium, the wrapped process is
completely CPU-bound, i.e. except of some logging output there is no I/O
whatsoever.

During one second of "application time", I am doing exactly 120 calls into
the application through three Cython-wrapped API functions. The
application uses some platform-dependent APIs, which I have also wrapped
with Cython, so that there are numerous callbacks into the Python realm per
call into the application. What I am observing now, is that the performance
per "application second" decreases (remember: executing code that does the
same thing on every cycle) and extending the number of loop iterations does
not seem to cause any bound to this decrease. In the log ouput below, you
can see the GC counts, which look innocent to me. The "real time" is
measured using "time.time()". The "top" utility does not suggest any memory
leak either. I am developing on WSL2, but I have checked that this
performance effect also happens on physical machines. Right now, I am
staring at "kcachegrind", but I have no idea, how to determine time series
for the performance of functions (I am not looking for those functions,
which need the most time, but for those, which consume more and more
execution time).

One more thing to look for could be memory fragmentation, but before that I
would like to ask the experts here for their ideas and experiences and/or
for tools, which could help to find the culprit.

2022-10-04 10:40:50|INFO |__main__ |Execution loop 0 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.06862711906433105 seconds real time.
> 2022-10-04 10:40:51|INFO |__main__ |Execution loop 100 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.08224177360534668 seconds real time.
> 2022-10-04 10:40:52|INFO |__main__ |Execution loop 200 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.08225250244140625 seconds real time.
> 2022-10-04 10:40:53|INFO |__main__ |Execution loop 300 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.10176873207092285 seconds real time.
> 2022-10-04 10:40:54|INFO |__main__ |Execution loop 400 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.10900592803955078 seconds real time.
> 2022-10-04 10:40:55|INFO |__main__ |Execution loop 500 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.12233948707580566 seconds real time.
> 2022-10-04 10:40:56|INFO |__main__ |Execution loop 600 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.14058256149291992 seconds real time.
> 2022-10-04 10:40:58|INFO |__main__ |Execution loop 700 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.14777183532714844 seconds real time.
> 2022-10-04 10:40:59|INFO |__main__ |Execution loop 800 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.15729451179504395 seconds real time.
> 2022-10-04 10:41:01|INFO |__main__ |Execution loop 900 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.17365813255310059 seconds real time.
> 2022-10-04 10:41:03|INFO |__main__ |Execution loop 1000 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.17772984504699707 seconds real time.
> 2022-10-04 10:41:05|INFO |__main__ |Execution loop 1100 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.1955263614654541 seconds real time.
> 2022-10-04 10:41:07|INFO |__main__ |Execution loop 1200 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.20046710968017578 seconds real time.
> 2022-10-04 10:41:09|INFO |__main__ |Execution loop 1300 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.22513842582702637 seconds real time.
> 2022-10-04 10:41:11|INFO |__main__ |Execution loop 1400 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.23578548431396484 seconds real time.
> 2022-10-04 10:41:13|INFO |__main__ |Execution loop 1500 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.24581527709960938 seconds real time.
> 2022-10-04 10:41:16|INFO |__main__ |Execution loop 1600 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.2541334629058838 seconds real time.
> 2022-10-04 10:41:19|INFO |__main__ |Execution loop 1700 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.26812195777893066 seconds real time.
> 2022-10-04 10:41:21|INFO |__main__ |Execution loop 1800 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.28777456283569336 seconds real time.
> 2022-10-04 10:41:24|INFO |__main__ |Execution loop 1900 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.3005337715148926 seconds real time.
> 2022-10-04 10:41:28|INFO |__main__ |Execution loop 2000 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.30992960929870605 seconds real time.
> 2022-10-04 10:41:31|INFO |__main__ |Execution loop 2100 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.32058119773864746 seconds real time.
> 2022-10-04 10:41:34|INFO |__main__ |Execution loop 2200 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.33020949363708496 seconds real time.
> 2022-10-04 10:41:37|INFO |__main__ |Execution loop 2300 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.34426307678222656 seconds real time.
> 2022-10-04 10:41:41|INFO |__main__ |Execution loop 2400 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.35851263999938965 seconds real time.
> 2022-10-04 10:41:45|INFO |__main__ |Execution loop 2500 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.3664553165435791 seconds real time.
> 2022-10-04 10:41:48|INFO |__main__ |Execution loop 2600 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.3767662048339844 seconds real time.
> 2022-10-04 10:41:52|INFO |__main__ |Execution loop 2700 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.39760732650756836 seconds real time.
> 2022-10-04 10:41:56|INFO |__main__ |Execution loop 2800 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.42221736907958984 seconds real time.
> 2022-10-04 10:42:01|INFO |__main__ |Execution loop 2900 done. GC
> counts = (381, 9, 3); 1 second of application time corresponds to
> 0.4237234592437744 seconds real time.

Thanks in advance,

Andreas

1
server_pubkey.txt

rocksolid light 0.9.81
clearnet tor