Workflow of bibo queries

[lingu]

The workflow of bibo queries use SageRun in Sage. SageRun drives an ATPA to perform a task for a QID.

The call path starts in scali invoking ProcRequestDefault. We optimize the timing of the steps and should make it complete in no more than 1s.

r1: scali
-> r3: getRequest
-> r5: ProcRequestDefalt
-> r7: queryMatch
-> r9: SageRun instances [1..llTaskCnt]
-> r11: atpa by user sage (atpa may log some info in atpa.log-$dd where dd is the datum number. Note that some log may be somewhere else.)
-> r13: atpa.sh by user sage (log in atpash.log-$dd, also check output files in the query's dir in fastdata))
-> r15: procone.py (log is perhaps in atpa.sh's log or procone2-$tycano.log)

Most of the log file locations are /thinker/local/today/users/$USER

We optimized r1 to r7 from 20+s to 3s by reducing memory footprint used by SageRun, skipping SageRunPrep and increasing atp count.

r9 and r11 still takes 13s. If we reduce the task count to 90, the time is reduced to 8s. With atpa.sh, it takes 10s.

---
20210813/lingu: log info
20210811/zhihao: link procone2.py
20201108/lingu: rename to be workflow.

[lingu]

A query may run in the following timing starting at 0025 for query 56.
25.45 issue: talk2thinker2 working for tok 002545292938784 [1108-00:25:45]
25.45 receive: received new case in /thinker/globe/soft/bibo/procuratorate/tests/newcase/newcase.txt [1108-00:25:45]
25.45 scali
25:47 thinkres start [2020-11-08 00:25:47] thinkres starts with --reqtype query --resdir /thinker/globe/soft/bibo/procuratorate/tests/res2 --casecnt 26 --out /thinker/globe/soft/bibo/procuratorate/tests/res2/res.res26.09 first wrid dir in qfastdir on limbo30-1 -- 24
26.09 first task 24 creates wrid dir in qfastdir
26.15 bibo.log last modification
26.29 last seen dir in qfastdir on limbo30-1 -- 126.seen

[lingu]

I commented out the invokation of atpa.sh in atpa, and run the query again around 0054 with query 64.

54:29 issue
54:31 thinkres
54:51 modification of earliest dir 24
54.59 bibo.log final modification
55.07 modification on 126.seen.

[lingu]

I try to reduce the amount of UPFS to be shared to others.

Run a query 0 around 0130 for query 16 without atpa.sh.
30:19 issue
30.31 first dir in qfastdir -- 24
30:44 last modified dir -- 126.seen
30:47 send results

[lingu]

I add back the call to atpa.sh, and run a query 40 around 0140.

40:32 issue
40:34 thinres
40:45 first dir in qfastdir
41:05 last modified dir 126.seen

[lingu]

I reduce llUpfsSmall to 0x10000000 (64M) and run inquire_zeng around 0152 for query 0 -- but sage crashed.

I made it 256MiB and it seems to work.

52:21 issue
52:48 first dir in qfastdir
53:05 last modified dir 120.seen

The perf is still bad.

[lingu]

I further increased sage_atp_count to 30 and re-installed sage.

Code:

[sage@limbo30-1 test]$ ./test_insert_zeng.sh
sending insert request ./processed/zengxingliang-newkey.json
return code: 200
insert success
[sage@limbo30-1 test]$

Then I tested inquiry for qid 32 around 0402.

Code:

[sage@limbo30-1 test]$ ./test_inquire_zeng.sh
sending inquire request ./processed/zengxingliang-inquire.json
Connected to Sage
.. matching doc limbo30-3
.. telling sage message M of 0 bytes 0x1bedde0 0x1beddec 0x1beddf0
.. heard R with qid 32
Hang up

02:09 issue
02:12 thinkres starts
02:13.28 firest dir (3) in qfastdir
02.28:18 last modified dir (126.seen) in qfastdir
02:38 send results

[lingu]

Tested query 40 without calling atpd.sh around 0853.

Code:

sending inquire request ./processed/zengxingliang-inquire.json
Connected to Sage
.. matching doc limbo30-3
.. telling sage message M of 0 bytes 0xa1ade0 0xa1adec 0xa1adf0
.. heard R with qid 40
Hang up
{
"code": 404,
"msg": "not found",
"children": [
]
}

parse error: Invalid numeric literal at line 1, column 10
return code:
inquire failed
[sage@limbo30-1 test]$
[lingu@limbo30-1 res2]$ ll -tr 40|less
[lingu@limbo30-1 res2]$ stat 40/15 40/126.seen/
  File: 40/15
  Size: 40              Blocks: 0          IO Block: 4096   directory
Device: 16h/22d Inode: 3254655     Links: 2
Access: (0755/drwxr-xr-x)  Uid: ( 8005/    sage)   Gid: ( 8005/    sage)
Access: 2020-11-08 08:54:00.522582201 +0800
Modify: 2020-11-08 08:54:00.522582201 +0800
Change: 2020-11-08 08:54:00.522582201 +0800
Birth: -
  File: 40/126.seen/
  Size: 40              Blocks: 0          IO Block: 4096   directory
Device: 16h/22d Inode: 3252830     Links: 2
Access: (0755/drwxr-xr-x)  Uid: ( 8005/    sage)   Gid: ( 8005/    sage)
Access: 2020-11-08 08:54:13.254652429 +0800
Modify: 2020-11-08 08:54:13.254652429 +0800
Change: 2020-11-08 08:54:13.254652429 +0800
Birth: -

53:57 issue
54:00 first dir
54:13 last dir

[lingu]

20201108 0935/lingu runs query 48 with sacli requesting 100 tasks without calling atpa.sh.

Code:

[sage@limbo30-1 test]$ ./test_inquire_zeng.sh
sending inquire request ./processed/zengxingliang-inquire.json
Connected to Sage
.. matching doc limbo30-3
.. telling sage message M of 0 bytes 0x21fade0 0x21fadec 0x21fadf0
.. heard R with qid 48
Hang up
{
"code": 404,
"msg": "not found",
"children": [
]
}

parse error: Invalid numeric literal at line 1, column 10
return code:
inquire failed
[sage@limbo30-1 test]$
...
[lingu@limbo30-1 res2]$ ll -tr 48|tail -n1
drwxr-xr-x 2 sage sage 40 Nov  8 09:35 99.seen
[lingu@limbo30-1 res2]$ ll -tr 48|head -n2
total 0
drwxr-xr-x 2 sage sage 40 Nov  8 09:35 18
[lingu@limbo30-1 res2]$ stat 48/18 48/99.seen/
  File: 48/18
  Size: 40              Blocks: 0          IO Block: 4096   directory
Device: 16h/22d Inode: 3260613     Links: 2
Access: (0755/drwxr-xr-x)  Uid: ( 8005/    sage)   Gid: ( 8005/    sage)
Access: 2020-11-08 09:35:46.670376313 +0800
Modify: 2020-11-08 09:35:46.670376313 +0800
Change: 2020-11-08 09:35:46.670376313 +0800
Birth: -
  File: 48/99.seen/
  Size: 40              Blocks: 0          IO Block: 4096   directory
Device: 16h/22d Inode: 3258564     Links: 2
Access: (0755/drwxr-xr-x)  Uid: ( 8005/    sage)   Gid: ( 8005/    sage)
Access: 2020-11-08 09:35:56.458430071 +0800
Modify: 2020-11-08 09:35:56.458430071 +0800
Change: 2020-11-08 09:35:56.458430071 +0800
Birth: -
[lingu@limbo30-1 res2]$

35:43 issue
35:46 first fast dir
35:56 last fast dir

Then I reduced task count to 90 around 0944.

Code:

[lingu@limbo30-1 res2]$ ll -tr 56|head -n2
total 0
drwxr-xr-x 2 sage sage 40 Nov  8 09:44 3
[lingu@limbo30-1 res2]$ ll -tr 56|tail -n1
drwxr-xr-x 2 sage sage 40 Nov  8 09:44 90.seen
[lingu@limbo30-1 res2]$ stat 56/3 56/90.seen/
  File: 56/3
  Size: 40              Blocks: 0          IO Block: 4096   directory
Device: 16h/22d Inode: 3250164     Links: 2
Access: (0755/drwxr-xr-x)  Uid: ( 8005/    sage)   Gid: ( 8005/    sage)
Access: 2020-11-08 09:44:49.019355019 +0800
Modify: 2020-11-08 09:44:49.019355019 +0800
Change: 2020-11-08 09:44:49.019355019 +0800
Birth: -
  File: 56/90.seen/
  Size: 40              Blocks: 0          IO Block: 4096   directory
Device: 16h/22d Inode: 3257642     Links: 2
Access: (0755/drwxr-xr-x)  Uid: ( 8005/    sage)   Gid: ( 8005/    sage)
Access: 2020-11-08 09:44:57.774403104 +0800
Modify: 2020-11-08 09:44:57.774403104 +0800
Change: 2020-11-08 09:44:57.774403104 +0800
Birth: -
[lingu@limbo30-1 res2]$

44:46 issue
44:49 first fast dir
44:57 last fast dir

[lingu]

20201108 1000/lingu runs query 64.

Code:

[sage@limbo30-1 test]$ ./test_inquire_zeng.sh
sending inquire request ./processed/zengxingliang-inquire.json
Connected to Sage
.. matching doc limbo30-3
.. telling sage message M of 0 bytes 0x1725de0 0x1725dec 0x1725df0
.. heard R with qid 64
Hang up
{
"code": 200,
"msg": "ok",
"children": [
  {
   "keys": [
     {
   "keys": [
     {
       "type": "key3",
       "value": "计算机信息系统",
       "detailid": "087b2085e4a911ea987a005056c00001"
     },
     {
       "type": "key1",
       "value": "破坏计算机信息系统",
       "detailid": "087b2085e4a911ea987a005056c00001"
     },
     {
       "type": "key3",
       "value": "破坏计算机信息系统",
       "detailid": "087b5ca4e4a911ea987a005056c00001"
     },
...
       "type": "key2",
       "value": "智能手机终端",
       "detailid": "087b61a1e4a911ea987a005056c00001"
     },
     {
       "type": "key1",
       "value": "破坏计算机信息系统",
       "detailid": "087b61a1e4a911ea987a005056c00001"
     }
   ],
   "caseid": "67be261c9e6311eabceb005056c00001",
   "caseyear": 2017,
   "casetitle": "曾兴亮、王玉生破坏计算机信息系统案",
   "casetype": "最高人民检察院指导性案例",
   "caserate": "5.00",
   "caseaction": "破坏计算机信息系统罪",
   "score": 100
  }
]
}

parse error: Invalid numeric literal at line 1, column 10
return code:
inquire failed
[sage@limbo30-1 test]$

bibo.log shows the following.

Code:

received new case in /thinker/globe/soft/bibo/procuratorate/tests/newcase/newcase.txt [1108-10:00
:28]
casetype is: query
  querying case /thinker/globe/soft/bibo/procuratorate/tests/newcase/newcase.txt
      torun     /thinker/globe/.think/run/sacli  --helper limbo30-3 match /thinker/globe/soft/bibo/p
rocuratorate/tests/newcase/newcase.txt
      sacli completes with exit code 0
    finish query
      The query 64 is of "query" type, run getresults()
    collecting results from 27 cases in /thinker/globe/soft/bibo/procuratorate/tests/res2
[2020-11-08 10:00:30] thinkres starts with --reqtype query --resdir /thinker/globe/soft/bibo/procura
torate/tests/res2 --casecnt 27 --out /thinker/globe/soft/bibo/procuratorate/tests/res2/res.res
  tycano: x
  casecnt: 27
  more args
      scrutinize /thinker/globe/soft/bibo/procuratorate/tests/res2 for 27 cases
      scrutinize fns res.res
      dozed for 0
      scrutinize fns res.res
...
      scrutinize fns res.res
      dozed for 24.7
    producing output with results
    thinkres completed with /thinker/globe/soft/bibo/procuratorate/tests/res2/res.res
          run1 exits with 0 for /usr/bin/python /thinker/globe/soft/bibo/triage/thinkres.py --reqtype query --resdir /thinker/globe/soft/bibo/procuratorate/tests/res2 --casecnt 27 --out /thinker/globe/soft/bibo/procuratorate/tests/res2/res.res
    Sending results for casetype query: [1108-10:00:57]
{
"code": 200,
"msg": "ok",
"children": [
  {
   "keys": [
     {
       "type": "key3",
       "value": "计算机信息系统",
       "detailid": "087b2085e4a911ea987a005056c00001"
   "caseyear": 2017,
   "casetitle": "曾兴亮、王玉生破坏计算机信息系统案",
   "casetype": "最高人民检察院指导性案例",
   "caserate": "5.00",
   "caseaction": "破坏计算机信息系统罪",
   "score": 100
  }
]
}

      grep 200 in /thinker/globe/soft/bibo/procuratorate/tests/res2/res.res returns 0
      triage() completes with 0
      work() toret 0
    talk2thinker returns 0 for qid 64

00:28 issue
00:30 thinkres
00:32 first fast dir
00:42 last fast dir
00:57 send result