[Geoserver-users] Production error logging

GeoServer GeoServer User
1

Hi,

I know the GeoServer logging has been mentioned before and that more development could be done on the logging profiles were funding and resources available but I was wondering if the existing production log actually contains any reference to the database delays?

Our ICT departments are busy at work changing over hardware etc. and we are trying to determine whether or not this is impacting disk read/write speeds and connections. Our spatial database is provided by an Oracle database and the cached content is on Windows disk drives so there are a number of factors. I have mentioned before that I wanted to try and get information about each step in the rendering process into the production log so that you might have say a percentage of the time taken for each request logged. This might be in the audit logging but it would effectively split the request into waiting (GeoServer queue), data acquisition (read from database or file system), tile rendering and then perhaps download time (back to the user).

Clearly that may already exist in GeoTools logging and it would probably take a lot of work if it was completely new development but I was wondering about the timeout message.

If the rendering times out we currently get:

org.geoserver.platform.ServiceException: This request used more time than allowed and has been forcefully stopped. Max rendering time is 60.0s

Would it be possible to include the step if failed on at this point?

So it might read:

org.geoserver.platform.ServiceException: This request used more time than allowed and has been forcefully stopped during data read. Max rendering time is 60.0s

org.geoserver.platform.ServiceException: This request used more time than allowed and has been forcefully stopped during rendering. Max rendering time is 60.0s

I believe my current issue is because the database is too slow responding but we have a lot of layers and spatial indices can be broken in a number of ways. It would be great if we could look through the logs and identify if slow tiles are failing at the data acquisition phase rather than the GeoServer rendering phase.

Or perhaps that is already possible?

Please note, I am referring to the production logging profile but we do use audit logging and perhaps that sort of information should be in the audit logs instead.

Any thoughts would be great, sorry if it has already been discussed.

Cheers,

Paul

2

Hi Paul,
I can see there would be a lot of value in adding a datasource timeout error to production profile logging. I’m less sure about logging all timings within the “production” logging profile due to the overhead it would add.
However a new profile for “performance” level logging would be really useful, and is certainly something I could have used a number of times in the past. Maybe it’s something you can get Dorset CC to sponsor?

On the issue of your immediate problem, the best way to determine how lax your database is being is to query the database itself. I’d suggest something like:
a) Get a copy of Jmeter and set it up to query your database (i.e. https://jmeter.apache.org/usermanual/build-db-test-plan.html)
b) Determine what the SQL queries to the database look like for your layers, as they come from GeoServer (GeoTools debug logging I believe is the one you want for that).
c) Use the URL’s from (b) to form the basis of automated, random queries to the database (you change the bbox on a per-request basis).
d) Make it also query other datasets by changing the table referenced.

The output of this will be aggregated data indicating how fast (or not) your database is, and should indicate which datasets need optimisation.

If you do this properly, you’ll be able to use the resulting test plan long-term as either/both a kind of “smoke test” for the performance of your database, and to ensure that layers are all working.

For bonus points, this should be fairly simple to duplicate and then tweak to make the same requests of via HTTP to GeoServer in the form of WMS/WFS requests. Ideally not at the same time for the same queries though (caching).

Cheers,
Jonathan

---- On Tue, 15 Aug 2017 08:46:43 +0100 Paul Wittle via Geoserver-usersgeoserver-users@lists.sourceforge.net wrote ----

Hi,

I know the GeoServer logging has been mentioned before and that more development could be done on the logging profiles were funding and resources available but I was wondering if the existing production log actually contains any reference to the database delays?

Our ICT departments are busy at work changing over hardware etc. and we are trying to determine whether or not this is impacting disk read/write speeds and connections. Our spatial database is provided by an Oracle database and the cached content is on Windows disk drives so there are a number of factors. I have mentioned before that I wanted to try and get information about each step in the rendering process into the production log so that you might have say a percentage of the time taken for each request logged. This might be in the audit logging but it would effectively split the request into waiting (GeoServer queue), data acquisition (read from database or file system), tile rendering and then perhaps download time (back to the user).

Clearly that may already exist in GeoTools logging and it would probably take a lot of work if it was completely new development but I was wondering about the timeout message.

If the rendering times out we currently get:

org.geoserver.platform.ServiceException: This request used more time than allowed and has been forcefully stopped. Max rendering time is 60.0s

Would it be possible to include the step if failed on at this point?

So it might read:

org.geoserver.platform.ServiceException: This request used more time than allowed and has been forcefully stopped during data read. Max rendering time is 60.0s

org.geoserver.platform.ServiceException: This request used more time than allowed and has been forcefully stopped during rendering. Max rendering time is 60.0s

I believe my current issue is because the database is too slow responding but we have a lot of layers and spatial indices can be broken in a number of ways. It would be great if we could look through the logs and identify if slow tiles are failing at the data acquisition phase rather than the GeoServer rendering phase.

Or perhaps that is already possible?

Please note, I am referring to the production logging profile but we do use audit logging and perhaps that sort of information should be in the audit logs instead.

Any thoughts would be great, sorry if it has already been discussed.

Cheers,

Paul

“This e-mail is intended for the named addressee(s) only and may contain information about individuals or other sensitive information and should be handled accordingly. Unless you are the named addressee (or authorised to receive it for the addressee) you may not copy or use it, or disclose it to anyone else. If you have received this email in error, kindly disregard the content of the message and notify the sender immediately. Please be aware that all email may be subject to recording and/or monitoring in accordance with relevant legislation.” ------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world’s most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot_______________________________________________
Geoserver-users mailing list

Please make sure you read the following two resources before posting to this list:

Geoserver-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/geoserver-users

3

Thanks for that Jonathan,

We have tried doing that sort of tracking in the past and I worked out in the past that logging with the GeoTools profile is helpful in finding the SQL GeoServer is making.

It is not too bad doing that when you know there is a problem it is the not knowing that gets me. GeoServer tends to log hundreds of lines for simple errors like a layer missing a default style so our logs tend to be big and unwieldly. I think the datasource timeout error would be the most useful update.

I’m still hoping to be able to join in the development work at some point but I don’t have enough experience with JAVA development and childcare has made it hard to find time to go on any courses. Getting myself good enough to help still seems the most sensible direction at the moment as UK local authorities are not really spending on this sort of thing at the moment. My time may be more of a sensible target but unless I can find a decent course or mentor; I doubt that will be anytime soon.

Anyway, thanks again for the advice; I will definitely use it as much as I can.

Paul

···

From: Jonathan Moules [mailto:jonathan-lists@…7221…]
Sent: 21 August 2017 14:26
To: Paul Wittle <P.Wittle@…7193…>
Cc: ‘geoserver-users@lists.sourceforge.net’ geoserver-users@lists.sourceforge.net
Subject: Re: [Geoserver-users] Production error logging

Hi Paul,
I can see there would be a lot of value in adding a datasource timeout error to production profile logging. I’m less sure about logging all timings within the “production” logging profile due to the overhead it would add.
However a new profile for “performance” level logging would be really useful, and is certainly something I could have used a number of times in the past. Maybe it’s something you can get Dorset CC to sponsor?

On the issue of your immediate problem, the best way to determine how lax your database is being is to query the database itself. I’d suggest something like:
a) Get a copy of Jmeter and set it up to query your database (i.e. https://jmeter.apache.org/usermanual/build-db-test-plan.html)
b) Determine what the SQL queries to the database look like for your layers, as they come from GeoServer (GeoTools debug logging I believe is the one you want for that).
c) Use the URL’s from (b) to form the basis of automated, random queries to the database (you change the bbox on a per-request basis).
d) Make it also query other datasets by changing the table referenced.

The output of this will be aggregated data indicating how fast (or not) your database is, and should indicate which datasets need optimisation.

If you do this properly, you’ll be able to use the resulting test plan long-term as either/both a kind of “smoke test” for the performance of your database, and to ensure that layers are all working.

For bonus points, this should be fairly simple to duplicate and then tweak to make the same requests of via HTTP to GeoServer in the form of WMS/WFS requests. Ideally not at the same time for the same queries though (caching).

Cheers,
Jonathan

---- On Tue, 15 Aug 2017 08:46:43 +0100 Paul Wittle via Geoserver-users<geoserver-users@lists.sourceforge.net> wrote ----

Hi,

I know the GeoServer logging has been mentioned before and that more development could be done on the logging profiles were funding and resources available but I was wondering if the existing production log actually contains any reference to the database delays?

Our ICT departments are busy at work changing over hardware etc. and we are trying to determine whether or not this is impacting disk read/write speeds and connections. Our spatial database is provided by an Oracle database and the cached content is on Windows disk drives so there are a number of factors. I have mentioned before that I wanted to try and get information about each step in the rendering process into the production log so that you might have say a percentage of the time taken for each request logged. This might be in the audit logging but it would effectively split the request into waiting (GeoServer queue), data acquisition (read from database or file system), tile rendering and then perhaps download time (back to the user).

Clearly that may already exist in GeoTools logging and it would probably take a lot of work if it was completely new development but I was wondering about the timeout message.

If the rendering times out we currently get:

org.geoserver.platform.ServiceException: This request used more time than allowed and has been forcefully stopped. Max rendering time is 60.0s

Would it be possible to include the step if failed on at this point?

So it might read:

org.geoserver.platform.ServiceException: This request used more time than allowed and has been forcefully stopped during data read. Max rendering time is 60.0s

org.geoserver.platform.ServiceException: This request used more time than allowed and has been forcefully stopped during rendering. Max rendering time is 60.0s

I believe my current issue is because the database is too slow responding but we have a lot of layers and spatial indices can be broken in a number of ways. It would be great if we could look through the logs and identify if slow tiles are failing at the data acquisition phase rather than the GeoServer rendering phase.

Or perhaps that is already possible?

Please note, I am referring to the production logging profile but we do use audit logging and perhaps that sort of information should be in the audit logs instead.

Any thoughts would be great, sorry if it has already been discussed.

Cheers,

Paul

“This e-mail is intended for the named addressee(s) only and may contain information about individuals or other sensitive information and should be handled accordingly. Unless you are the named addressee (or authorised to receive it for the addressee) you may not copy or use it, or disclose it to anyone else. If you have received this email in error, kindly disregard the content of the message and notify the sender immediately. Please be aware that all email may be subject to recording and/or monitoring in accordance with relevant legislation.” ------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world’s most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot_______________________________________________
Geoserver-users mailing list

Please make sure you read the following two resources before posting to this list:

Geoserver-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/geoserver-users