Is there a different timeout when calling an interface procedure?

dcoun · 2022-09-23 13:40:07

Using Delphi 11.1 I have a TRestHttpClient from mormot2 created with 30000msec timeount to connect to a mormot2 server in Linux compiled with FPC and call an interface.
The procedure of the interface called in the server, runs a query using a RetrieveListJson and it returns in 4-6 sec with the following error:

Project ErrorViewer.exe raised exception class EInterfaceFactory with message 'TInterfacedObjectFakeClient.FakeCall(IwbService.repsearch) failed: 'URI central/v1/wbService.repsearch ["{\"mver\":-1,\"typ\":-1,\"user\":-1,\"pver\":-1,\"tofind\":\"\",\"term\":-1,\"sdat\":\"2022-09-13\",\"edat\":\"2022-09-23\"}",0,20] returned status 'Not Found' (404 - Network problem or request timeout)''.

Probably the query needs more time or the database that gets a lot of inserts per minute could not respond fast. But it seems to be from the client side and the timeout of 30.000msec for the three constructor's arguments is not taken into account. I have also added a "timeout=30" to ZEOS options during connection without success

Can you think a possible cause?
Thank you in advance

ab · 2022-09-23 15:37:14

Try to enable the logs in verbose mode on both client and server sides.

You may find some more information.

dcoun · 2022-09-23 18:44:34

The problem is on the server. The cpu load goes to the sky and I have no logs due to delayed write. I will check to find the option to write at once the logs. Thank you

dcoun · 2022-09-23 18:52:37

The client gives the following:

20220923 18480812  -    00.092.557
20220923 18480949  +    mormot.soa.client.TServiceFactoryClient(07f13f70).InternalInvoke IwbService.repsearch("{\"mver\":-1,\"typ\":-1,\"user\":-1,\"pver\":-1,\"tofind\":\"\",\"term\":-1,\"sdat\":\"2022-09-13\",\"edat\":\"2022-09-23\"}",0,20) 
20220923 18480949  +    	mormot.rest.http.client.TRestHttpClientWebsockets(07db7a80).InternalUri POST
20220923 18480949 trace 		mormot.rest.http.client.TRestHttpClientWebsockets(07db7a80) InternalRequest POST calling THttpClientWebSockets(07db7840).Request
20220923 18480949 trace 		mormot.net.ws.client.TWebSocketProcessClient(07d20b20) NotifyCallback(central/v1/wbService.repsearch,wscBlockWithAnswer)
20220923 18480949 trace 		mormot.net.ws.client.TWebSocketProcessClient(07d20b20) SendFrame host.domain.info r000007 focBinary len=404
20220923 18481505 warn  		mormot.net.ws.client.TWebSocketProcessClient(07d20b20) NotifyCallback TIMEOUT a000007
20220923 18481505 clnt  		mormot.rest.http.client.TRestHttpClientWebsockets(07db7a80) POST central/v1/wbService.repsearch status=404 len=0 state=0
20220923 18481505  -    	05.296.380
20220923 18481505 trace 	mormot.rest.http.client.TRestHttpClientWebsockets(07db7a80) POST central/v1/wbService.repsearch returned 404 (Not Found) with message Not Found

ab · 2022-09-23 20:12:55

And the server ?

ab · 2022-09-23 20:14:34

Since you are using websockets, use a dedicated thread and the "long work" pattern instead.

dcoun · 2022-09-24 11:13:49

To be honest I was a bit lost in logs in the server. After that I setup the service to include threadid, to flush every second and I disabled the upgrade to websockets in client.
Now the client hangs till the timeout of 30seconds (it was probably the websocket upgrade) and as you proposed in such a case it will be better to create a thread and return result with websocket response.
But the first problem was that with websocket in 4-5 seconds the request was finished with timeout (probably due to the following exception).

The other interesting point is that the LIMIT keyword part in the sql query is missing (I had it in FormatSqlWhere) when executing RetrieveListJson, so the returned data was much more than expected without paging.
The result is an exception due to big number of returned resutls that caused the extreme load....

See the logs in the https://gist.github.com/dkounal/1d32fda … ca06a84362

Running the query from HeidiSQL I got the following

/* Affected rows: 0  Found rows: 734.492  Warnings: 0  Duration for 1 query: 0,453 sec. (+ 29,047 sec. network) */

So, when LIMIT is allowed and which alternate to RetrieveListJson do you recommend to have paging in results?
Thank you in advance

Last edited by dcoun (2022-09-24 15:09:08)

ab · 2022-09-24 14:00:40

There is certainly a SQLite3 virtual table involved in your query, which may be unable to properly translate the LIMIT operation.
How is your service implemented?
Try to debug a little on the server side. What is weird is that there is no SQLite3 virtual table statement logged... it should appear in the logs. And the LIMIT clause should be properly handled by the mORMot SQL parser, and bypass the SQLite3 virtual table.
(and please follow the forum rules, and don't publish in the thread forum messages huge logs as you did - or huge source code - and use e.g. a gist instead)

My advice would be to directly call the external DB without the ORM, in your case. With the proper LIMIT clause.
Note that your DB network seems pretty slow.

dcoun · 2022-09-24 14:34:10

Starting from the end:
network is not slow. the 29sec shown by HeidiSQL is the time needed by mysql_store_result as shown here: https://www.heidisql.com/forum.php?t=36841
Mormot2 seems to need at least the half time. But it is a table which could have 1 million inserts every 12h

I tried to find in the log that they are connected with the request. How can I identify the line that has to do with SQLite3 virtual table?
I will try to debug it in delphi.

dcoun · 2022-09-24 15:07:55

The problem for the limit is in mormot.db.core, constructor TSelectStatement.Create(const SQL: RawUtf8; const GetFieldIndex: TOnGetFieldIndex; const SimpleFields: TSelectStatementSelectDynArray);

called by mormot.orm.sql 's TRestStorageExternal.AdaptSqlForEngineList(var SQL: RawUtf8): boolean;

it returns the limit=0 in the following query

'SELECT RowID,dat,typ,mid,termnam,mariadbver,pchrver,user,ctid,app,uid,dver,build,msg FROM RepErrors WHERE dat > :(20220913): AND dat < :(20220925): ORDER BY dat DESC Limit 0,20'

How is your service implemented?

Help me with what information you need..

Last edited by dcoun (2022-09-24 15:20:53)

ab · 2022-09-24 16:46:29

Limit 0,20 is a valid MySQL syntax...

dcoun · 2022-09-24 16:50:09

ab wrote:

Limit 0,20 is a valid MySQL syntax...

I think it is for sqlite also
https://www.sqlite.org/lang_select.html

It needs it as 20,0 and mormot is too clever....I think
Thanks a lot again @ab

Last edited by dcoun (2022-09-24 17:07:03)

dcoun · 2022-09-24 17:05:59

So, no exception now and it works
I will try it again now with websockets.
I noticed that you are doing an excellent work with Letsencrypt. When will it be ready to test it?
as alternate what is the correct configuration in nginx for using >100 clients with websockets behind nginx?

dcoun · 2022-09-24 18:05:07

Just an other problem with RetrieveListJson and LIMIT/OFFSET
I am running the following command:

srvdb.Orm.RetrieveListJson(TormRepErrors,'dat > :(20220913): AND dat < :(20220925): ORDER BY dat DESC LIMIT 20 OFFSET 0',[],'*');

The query returned by mormot.orm.sql 's TRestStorageExternal.AdaptSqlForEngineList(var SQL: RawUtf8): boolean; is

select ID,dat,typ,mid,termnam,mariadbver,pchrver,user_ as user,ctid,app,uid,dver,build,msg from reperrors where dat>:(20220913): and dat<:(20220925): order by dat desc limit 20

The next page will be retrieved with

srvdb.Orm.RetrieveListJson(TormRepErrors,'dat > :(20220913): AND dat < :(20220925): ORDER BY dat DESC LIMIT 20 OFFSET 20',[],'*');

But now the query returned by mormot.orm.sql 's TRestStorageExternal.AdaptSqlForEngineList(var SQL: RawUtf8): boolean; is

SELECT RowID,dat,typ,mid,termnam,mariadbver,pchrver,user,ctid,app,uid,dver,build,msg FROM RepErrors WHERE dat > :(20220913): AND dat < :(20220925): ORDER BY dat DESC LIMIT 20 OFFSET 20

Can you notice that the first return is "ID" but in the second it is returning a "RowID"? it seems that in the second, it does not "touch" the initial query.
The problem is that resulting JSON has different the first field if searched by name

Last edited by dcoun (2022-09-24 18:06:59)

mORMot Open Source

#1 2022-09-23 13:40:07

Is there a different timeout when calling an interface procedure?

#2 2022-09-23 15:37:14

Re: Is there a different timeout when calling an interface procedure?

#3 2022-09-23 18:44:34

Re: Is there a different timeout when calling an interface procedure?

#4 2022-09-23 18:52:37

Re: Is there a different timeout when calling an interface procedure?

#5 2022-09-23 20:12:55

Re: Is there a different timeout when calling an interface procedure?

#6 2022-09-23 20:14:34

Re: Is there a different timeout when calling an interface procedure?

#7 2022-09-24 11:13:49

Re: Is there a different timeout when calling an interface procedure?

#8 2022-09-24 14:00:40

Re: Is there a different timeout when calling an interface procedure?

#9 2022-09-24 14:34:10

Re: Is there a different timeout when calling an interface procedure?

#10 2022-09-24 15:07:55

Re: Is there a different timeout when calling an interface procedure?

#11 2022-09-24 16:46:29

Re: Is there a different timeout when calling an interface procedure?

#12 2022-09-24 16:50:09

Re: Is there a different timeout when calling an interface procedure?

#13 2022-09-24 17:05:59

Re: Is there a different timeout when calling an interface procedure?

#14 2022-09-24 18:05:07

Re: Is there a different timeout when calling an interface procedure?

Board footer