Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

tests: fix t151 recv_runcmd test code. #1765

Merged
merged 1 commit into from Jul 26, 2023

Conversation

kang-hyuck
Copy link
Contributor

@kang-hyuck kang-hyuck commented Jul 18, 2023

problem:
Fix the issue that prints no results in prerun test. Nonetheless the recv server hasn't finished processing the client's data, recv server is forcibly terminated and reading the results from the pipe. recv_cmd server needs time to process record_cmd client's data.

solution:
Use epoll to check server's pipe status.

Fixed: #1578 recv runcmd run test need result (x86_64, aarch64)

@MichelleJin12
Copy link
Contributor

Hello @kang-hyuck, thank you for your contribution. :D
Please remove the duplicate signature and the commit b13eb7f.

@MichelleJin12
Copy link
Contributor

I've tested it in Ubuntu 22.04 x86_64.
Most tests are OK, but I get random NGs. I don't know why yet.

(venv) vagrant@vagrant:~/uftrace_kang-kyuck/tests$ ./runtest.py -d 151 -j3
Start 1 tests without worker pool

Compiler                  gcc                                           clang
Runtime test case         pg             finstrument-fu fpatchable-fun  pg             finstrument-fu fpatchable-fun
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os  O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os
151 recv_runcmd         : OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK  OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK


runtime test stats
====================
total    30  Tests executed (success: 100.00%)
  OK:    30  Test succeeded
  OK:     0  Test succeeded (with some fixup)
  NG:     0  Different test result
  NZ:     0  Non-zero return value
  SG:     0  Abnormal exit by signal
  TM:     0  Test ran too long
  BI:     0  Build failed
  LA:     0  Unsupported Language
  SK:     0  Skipped
(venv) vagrant@vagrant:~/uftrace_kang-kyuck/tests$ ./runtest.py -d 151 -j8
Start 1 tests without worker pool

Compiler                  gcc                                           clang
Runtime test case         pg             finstrument-fu fpatchable-fun  pg             finstrument-fu fpatchable-fun
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os  O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os
t151_recv_runcmd: diff result of clang -finstrument-functions -O1
--- expect	2023-07-19 22:26:49.425558432 +0000
+++ result	2023-07-19 22:26:49.425558432 +0000
@@ -1,9 +1 @@
-main() {
-   a() {
-     b() {
-       c() {
-         getpid();
-       } /* c */
-     } /* b */
-   } /* a */
- } /* main */
+

t151_recv_runcmd: diff result of clang -finstrument-functions -O2
--- expect	2023-07-19 22:26:49.525608436 +0000
+++ result	2023-07-19 22:26:49.525608436 +0000
@@ -1,9 +1 @@
-main() {
-   a() {
-     b() {
-       c() {
-         getpid();
-       } /* c */
-     } /* b */
-   } /* a */
- } /* main */
+

151 recv_runcmd         : OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK  OK OK OK OK OK OK NG NG OK OK OK OK OK OK OK


runtime test stats
====================
total    30  Tests executed (success: 93.33%)
  OK:    28  Test succeeded
  OK:     0  Test succeeded (with some fixup)
  NG:     2  Different test result
  NZ:     0  Non-zero return value
  SG:     0  Abnormal exit by signal
  TM:     0  Test ran too long
  BI:     0  Build failed
  LA:     0  Unsupported Language
  SK:     0  Skipped
(venv) vagrant@vagrant:~/uftrace_kang-kyuck/tests$ ./runtest.py -d 151 -j8
Start 1 tests without worker pool

Compiler                  gcc                                           clang
Runtime test case         pg             finstrument-fu fpatchable-fun  pg             finstrument-fu fpatchable-fun
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os  O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os
151 recv_runcmd         : OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK  OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK


runtime test stats
====================
total    30  Tests executed (success: 100.00%)
  OK:    30  Test succeeded
  OK:     0  Test succeeded (with some fixup)
  NG:     0  Different test result
  NZ:     0  Non-zero return value
  SG:     0  Abnormal exit by signal
  TM:     0  Test ran too long
  BI:     0  Build failed
  LA:     0  Unsupported Language
  SK:     0  Skipped
(venv) vagrant@vagrant:~/uftrace_kang-kyuck/tests$ ./runtest.py -d 151 -j8
Start 1 tests without worker pool

Compiler                  gcc                                           clang
Runtime test case         pg             finstrument-fu fpatchable-fun  pg             finstrument-fu fpatchable-fun
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os  O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os
t151_recv_runcmd: diff result of clang -pg -O2
--- expect	2023-07-19 22:33:28.036779923 +0000
+++ result	2023-07-19 22:33:28.036779923 +0000
@@ -1,9 +1 @@
-main() {
-   a() {
-     b() {
-       c() {
-         getpid();
-       } /* c */
-     } /* b */
-   } /* a */
- } /* main */
+

151 recv_runcmd         : OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK  OK OK NG OK OK OK OK OK OK OK OK OK OK OK OK


runtime test stats
====================
total    30  Tests executed (success: 96.67%)
  OK:    29  Test succeeded
  OK:     0  Test succeeded (with some fixup)
  NG:     1  Different test result
  NZ:     0  Non-zero return value
  SG:     0  Abnormal exit by signal
  TM:     0  Test ran too long
  BI:     0  Build failed
  LA:     0  Unsupported Language
  SK:     0  Skipped

@honggyukim
Copy link
Collaborator

Hi @kang-hyuck, thanks for the patch. It looks good but I still see some random failures as @MichelleJin12 mentioned.

$ ./runtest.py -d 151 
Start 1 tests without worker pool

Compiler                  gcc                                           clang                                       
Runtime test case         pg             finstrument-fu fpatchable-fun  pg             finstrument-fu fpatchable-fun
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os  O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os
t151_recv_runcmd: diff result of gcc -finstrument-functions -O3 -fno-ipa-sra
--- expect      2023-07-20 23:37:56.345633701 +0900
+++ result      2023-07-20 23:37:56.345633701 +0900
@@ -1,9 +1 @@
-main() {
-   a() {
-     b() {
-       c() {
-         getpid();
-       } /* c */
-     } /* b */
-   } /* a */
- } /* main */
+

151 recv_runcmd         : OK OK OK OK OK OK OK OK NG OK OK OK OK OK OK  OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK

@kang-hyuck kang-hyuck force-pushed the fix-t151_recv_runcmd branch 2 times, most recently from da2e4a1 to 13ac4fa Compare July 20, 2023 15:37
@kang-hyuck
Copy link
Contributor Author

thank you for your reviews ! :) @MichelleJin12 @honggyukim
I push new version of commit 13ac4fa which added self.file_p.flush() after self.file_p.write() and all test case is OK
Could I know versions of gcc and clang ? In my case, gcc is 9.4 and clang is 10.0.

In addition, I found that when random.randint(40000, 50000) was used to allocate random port in self.gen_port(), record_cmd task was blocked forever in sp.call(record_cmd, stderr=sp.PIPE). So I used a fixed port number such as self.port_num=1234, I can solve this issues. I didn't include it in the commit because I think it's a Linux network environment issue.

kh@peso:~/work/uftrace/tests$ ./runtest.py -d 151 -j32
Start 1 tests without worker pool

Compiler                  gcc                                           clang                                       
Runtime test case         pg             finstrument-fu fpatchable-fun  pg             finstrument-fu fpatchable-fun
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os  O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os
151 recv_runcmd         : OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK  OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK


runtime test stats
====================
total    30  Tests executed (success: 100.00%)
  OK:    30  Test succeeded
  OK:     0  Test succeeded (with some fixup)
  NG:     0  Different test result
  NZ:     0  Non-zero return value
  SG:     0  Abnormal exit by signal
  TM:     0  Test ran too long
  BI:     0  Build failed
  LA:     0  Unsupported Language
  SK:     0  Skipped
kh@peso:~/work/uftrace/tests$ ./runtest.py -d 151 -j32
Start 1 tests without worker pool

Compiler                  gcc                                           clang                                       
Runtime test case         pg             finstrument-fu fpatchable-fun  pg             finstrument-fu fpatchable-fun
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os  O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os
151 recv_runcmd         : OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK  OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK


runtime test stats
====================
total    30  Tests executed (success: 100.00%)
  OK:    30  Test succeeded
  OK:     0  Test succeeded (with some fixup)
  NG:     0  Different test result
  NZ:     0  Non-zero return value
  SG:     0  Abnormal exit by signal
  TM:     0  Test ran too long
  BI:     0  Build failed
  LA:     0  Unsupported Language
  SK:     0  Skipped
kh@peso:~/work/uftrace/tests$ ./runtest.py -d 151 -j32
Start 1 tests without worker pool

Compiler                  gcc                                           clang                                       
Runtime test case         pg             finstrument-fu fpatchable-fun  pg             finstrument-fu fpatchable-fun
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os  O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os
151 recv_runcmd         : OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK  OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK


runtime test stats
====================
total    30  Tests executed (success: 100.00%)
  OK:    30  Test succeeded
  OK:     0  Test succeeded (with some fixup)
  NG:     0  Different test result
  NZ:     0  Non-zero return value
  SG:     0  Abnormal exit by signal
  TM:     0  Test ran too long
  BI:     0  Build failed
  LA:     0  Unsupported Language
  SK:     0  Skipped
kh@peso:~/work/uftrace/tests$ ./runtest.py -d 151 -j32
Start 1 tests without worker pool

Compiler                  gcc                                           clang                                       
Runtime test case         pg             finstrument-fu fpatchable-fun  pg             finstrument-fu fpatchable-fun
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os  O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os
151 recv_runcmd         : OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK  OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK


runtime test stats
====================
total    30  Tests executed (success: 100.00%)
  OK:    30  Test succeeded
  OK:     0  Test succeeded (with some fixup)
  NG:     0  Different test result
  NZ:     0  Non-zero return value
  SG:     0  Abnormal exit by signal
  TM:     0  Test ran too long
  BI:     0  Build failed
  LA:     0  Unsupported Language
  SK:     0  Skipped
kh@peso:~/work/uftrace/tests$ ./runtest.py -d 151 -j32
Start 1 tests without worker pool

Compiler                  gcc                                           clang                                       
Runtime test case         pg             finstrument-fu fpatchable-fun  pg             finstrument-fu fpatchable-fun
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os  O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os
151 recv_runcmd         : OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK  OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK


runtime test stats
====================
total    30  Tests executed (success: 100.00%)
  OK:    30  Test succeeded
  OK:     0  Test succeeded (with some fixup)
  NG:     0  Different test result
  NZ:     0  Non-zero return value
  SG:     0  Abnormal exit by signal
  TM:     0  Test ran too long
  BI:     0  Build failed
  LA:     0  Unsupported Language
  SK:     0  Skipped
kh@peso:~/work/uftrace/tests$ ./runtest.py -d 151 -j32
Start 1 tests without worker pool

Compiler                  gcc                                           clang                                       
Runtime test case         pg             finstrument-fu fpatchable-fun  pg             finstrument-fu fpatchable-fun
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os  O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os
151 recv_runcmd         : OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK  OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK


runtime test stats
====================
total    30  Tests executed (success: 100.00%)
  OK:    30  Test succeeded
  OK:     0  Test succeeded (with some fixup)
  NG:     0  Different test result
  NZ:     0  Non-zero return value
  SG:     0  Abnormal exit by signal
  TM:     0  Test ran too long
  BI:     0  Build failed
  LA:     0  Unsupported Language
  SK:     0  Skipped

@MichelleJin12
Copy link
Contributor

This is my gcc and clang version

$ gcc --version
gcc (Ubuntu 11.3.0-1ubuntu1~22.04.1) 11.3.0

$ clang --version
Ubuntu clang version 14.0.0-1ubuntu1
Target: x86_64-pc-linux-gnu
Thread model: posix
InstalledDir: /usr/bin

When I tested with commit 13ac4fa, the NG rate seems to have decreased, but it still happens.

vagrant@vagrant:~/uftrace_kang-kyuck/tests$ ./runtest.py -d 151
Start 1 tests without worker pool

Compiler                  gcc                                           clang                                       
Runtime test case         pg             finstrument-fu fpatchable-fun  pg             finstrument-fu fpatchable-fun
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os  O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os
t151_recv_runcmd: diff result of gcc -fpatchable-function-entry=5 -Os -fno-ipa-sra
--- expect      2023-07-21 00:23:41.352019764 +0000
+++ result      2023-07-21 00:23:41.352019764 +0000
@@ -1,9 +1 @@
-main() {
-   a() {
-     b() {
-       c() {
-         getpid();
-       } /* c */
-     } /* b */
-   } /* a */
- } /* main */
+

t151_recv_runcmd: diff result of clang -fpatchable-function-entry=5 -O0
--- expect      2023-07-21 00:23:48.011347910 +0000
+++ result      2023-07-21 00:23:48.011347910 +0000
@@ -1,9 +1 @@
-main() {
-   a() {
-     b() {
-       c() {
-         getpid();
-       } /* c */
-     } /* b */
-   } /* a */
- } /* main */
+

151 recv_runcmd         : OK OK OK OK OK OK OK OK OK OK OK OK OK OK NG  OK OK OK OK OK OK OK OK OK OK NG OK OK OK OK

In addition, I found that when random.randint(40000, 50000) was used to allocate random port in self.gen_port(), record_cmd task was blocked forever in sp.call(record_cmd, stderr=sp.PIPE). So I used a fixed port number such as self.port_num=1234, I can solve this issues. I didn't include it in the commit because I think it's a Linux network environment issue.

I think the NG is caused by a random port that's already in use, so I put in code to check if that port is in use, but it's not a complete solution.

def gen_port(self):
    random.seed(time.time())
    port = False
    while (port == False):
        try:
            self.port = random.randint(40000, 60000)
            with socketserver.TCPServer(("127.0.0.1", self.port), None) as s:
                port = True
                pass
        except OSError as e:
            port = False
            break
    print(self.port)

If it's blocked by sp.call, I guess we could use timeout, which is an argument to sp.call.

Copy link
Owner

@namhyung namhyung left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for working on this. But the commit message is too long. Please break it not to exceed 72 characters in a line.

self.recv_p.terminate()

out = self.recv_p.communicate()[0].decode(errors='ignore')
self.file_p.write(out)
self.file_p.flush()
self.file_p.close()
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think you need to close the epoll object here.

@@ -42,10 +46,14 @@ def prerun(self, timeout):
record_cmd += ['t-' + self.name]
self.pr_debug('prerun command: ' + ' '.join(record_cmd))
sp.call(record_cmd, stderr=sp.PIPE)

epolls.poll(timeout=5)
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we use timeout parameter in the prerun() method directly?

wait for recv_cmd server to process record_cmd client's data.

Fixed: namhyung#1578 recv runcmd run test need result (x86_64, aarch64)
Signed-off-by: kang-hyuck <kang-hyuck@naver.com>
@kang-hyuck
Copy link
Contributor Author

I found that there is a temporarily NG port between 40000~50000.
If I fix self.port number to NG port number that was found on test, all case is NG.
I think we need to discuss port allocation policy.

Compiler                  gcc                                           clang                                       
Runtime test case         pg             finstrument-fu fpatchable-fun  pg             finstrument-fu fpatchable-fun
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os  O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os

151 recv_runcmd         : NG NG NG NG NG NG NG NG NG NG NG NG NG NG NG  NG NG NG NG NG NG NG NG NG NG NG NG NG NG NG

runtime test stats
====================
total    30  Tests executed (success: 0.00%)
  OK:     0  Test succeeded
  OK:     0  Test succeeded (with some fixup)
  NG:    30  Different test result
  NZ:     0  Non-zero return value
  SG:     0  Abnormal exit by signal
  TM:     0  Test ran too long
  BI:     0  Build failed
  LA:     0  Unsupported Language
  SK:     0  Skipped

But after some time, all tests were OK even if I use NG port before.

Compiler                  gcc                                           clang                                       
Runtime test case         pg             finstrument-fu fpatchable-fun  pg             finstrument-fu fpatchable-fun
------------------------: O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os  O0 O1 O2 O3 Os O0 O1 O2 O3 Os O0 O1 O2 O3 Os
151 recv_runcmd         : OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK  OK OK OK OK OK OK OK OK OK OK OK OK OK OK OK


runtime test stats
====================
total    30  Tests executed (success: 100.00%)
  OK:    30  Test succeeded
  OK:     0  Test succeeded (with some fixup)
  NG:     0  Different test result
  NZ:     0  Non-zero return value
  SG:     0  Abnormal exit by signal
  TM:     0  Test ran too long
  BI:     0  Build failed
  LA:     0  Unsupported Language
  SK:     0  Skipped

I found that all test code where using gen_port() are same results and issue up this problem. #1767

here is same issue case code:

  • t141_recv_basic.py
  • t142_recv_multi.py

Copy link
Owner

@namhyung namhyung left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

self.recv_p.terminate()

out = self.recv_p.communicate()[0].decode(errors='ignore')
self.file_p.write(out)
self.file_p.flush()
self.file_p.close()
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think close() implies flush() but maybe it's better to have it explicitly.

@namhyung namhyung merged commit c7c58d7 into namhyung:master Jul 26, 2023
3 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

recv runcmd run test need result (x86_64, aarch64)
4 participants