{"id":949,"date":"2009-08-18T17:04:12","date_gmt":"2009-08-18T21:04:12","guid":{"rendered":"http:\/\/fgiasson.com\/blog\/?p=949"},"modified":"2009-08-18T17:04:12","modified_gmt":"2009-08-18T21:04:12","slug":"structwsf-early-querying-metrics","status":"publish","type":"post","link":"https:\/\/fgiasson.com\/blog\/index.php\/2009\/08\/18\/structwsf-early-querying-metrics\/","title":{"rendered":"structWSF Early Querying Metrics"},"content":{"rendered":"

We have been running different structWSF instances for about two months now. Each instance is hosting different dataset(s) that are queried for different purposes. I think that it worth taking some time starting to analyze the querying stats of two of these instances of the early Alpha version of structWSF.<\/p>\n

The goal is to create some kind of checkpoints that we will be able to use in the future to check how the system improved or deteriorated. It is also to check what kind of metrics we could derive from the current logging system, and to check if we could find any bottle neck or issues with any of the endpoints.<\/p>\n

The data used to analyze the instance A span from the 2009-06-08 at 7:16:38 to the 2009-08-18 at 12:28:37.<\/p>\n

The data used to analyze the instance B span from the 2009-05-20 at 1:46:31to the 2009-08-18 at 12:40:28.<\/p>\n

structWSF Instance A<\/h3>\n

The instance A only has 1 dataset with about 1000 instance records in it. As we can notice bellow, the average time of a query to that instance for all web service endpoints is about 210 milliseconds.<\/p>\n\n\n\n\n
Number of queries<\/span><\/strong>
\n <\/span><\/td>\n		Average time for each query in seconds<\/span><\/strong><\/td>\n<\/tr>\n
27956<\/td>\n0.218252857656909<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n

The table bellow give us the total number of queries sent to each web service endpoint with an average time for each web service.<\/p>\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n
<\/td>\n<\/tr>\n
Web Service<\/span><\/strong><\/td>\nNumber of queries<\/strong><\/td>\nAverage time for each query in seconds<\/strong><\/td>\n<\/tr>\n
dataset_create<\/td>\n265<\/td>\n0.126993534699919<\/td>\n<\/tr>\n
converter\/tsv<\/td>\n48<\/td>\n0.128808428843714<\/td>\n<\/tr>\n
dataset_update<\/td>\n17<\/td>\n0.140141641392576<\/td>\n<\/tr>\n
dataset_read<\/td>\n11780<\/td>\n0.144073766884864<\/td>\n<\/tr>\n
auth_registrar_access<\/td>\n883<\/td>\n0.145781793788779<\/td>\n<\/tr>\n
converter\/bibtex<\/td>\n49<\/td>\n0.149710825511323<\/td>\n<\/tr>\n
auth_lister<\/td>\n1970<\/td>\n0.159979685066925<\/td>\n<\/tr>\n
search<\/td>\n1397<\/td>\n0.180938945980523<\/td>\n<\/tr>\n
browse<\/td>\n8949<\/td>\n0.199636802392004<\/td>\n<\/tr>\n
crud_read<\/td>\n638<\/td>\n0.241032384406063<\/td>\n<\/tr>\n
dataset_delete<\/td>\n263<\/td>\n0.420157149717388<\/td>\n<\/tr>\n
crud_delete<\/td>\n3<\/td>\n0.637878338496<\/td>\n<\/tr>\n
converter\/irv<\/td>\n792<\/td>\n0.661979901670313<\/td>\n<\/tr>\n
sparql<\/td>\n715<\/td>\n1.123084135322358<\/td>\n<\/tr>\n
crud_create<\/td>\n187<\/td>\n1.486844727060763<\/td>\n<\/tr>\n
<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n

This table gives the number of queries for each returned HTTP response status code by the endpoint. This kind of metrics is useful to debug potential issues<\/p>\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n
<\/td>\n<\/tr>\n
Web Service<\/span><\/strong><\/td>\nNumber of queries<\/strong><\/td>\nHTTP Response Status<\/span><\/strong><\/td>\n<\/tr>\n
auth_lister<\/td>\n1968<\/td>\n200<\/td>\n<\/tr>\n
auth_lister<\/td>\n2<\/td>\n400<\/td>\n<\/tr>\n
auth_registrar_access<\/td>\n883<\/td>\n200<\/td>\n<\/tr>\n
browse<\/td>\n8949<\/td>\n200<\/td>\n<\/tr>\n
converter\/bibtex<\/td>\n45<\/td>\n200<\/td>\n<\/tr>\n
converter\/bibtex<\/td>\n2<\/td>\n400<\/td>\n<\/tr>\n
converter\/bibtex<\/td>\n2<\/td>\n406<\/td>\n<\/tr>\n
converter\/irv<\/td>\n740<\/td>\n200<\/td>\n<\/tr>\n
converter\/irv<\/td>\n51<\/td>\n400<\/td>\n<\/tr>\n
converter\/irv<\/td>\n1<\/td>\n406<\/td>\n<\/tr>\n
converter\/tsv<\/td>\n43<\/td>\n200<\/td>\n<\/tr>\n
converter\/tsv<\/td>\n2<\/td>\n400<\/td>\n<\/tr>\n
converter\/tsv<\/td>\n3<\/td>\n406<\/td>\n<\/tr>\n
crud_create<\/td>\n66<\/td>\n200<\/td>\n<\/tr>\n
crud_create<\/td>\n116<\/td>\n400<\/td>\n<\/tr>\n
crud_create<\/td>\n5<\/td>\n500<\/td>\n<\/tr>\n
crud_delete<\/td>\n3<\/td>\n200<\/td>\n<\/tr>\n
crud_read<\/td>\n480<\/td>\n200<\/td>\n<\/tr>\n
crud_read<\/td>\n158<\/td>\n400<\/td>\n<\/tr>\n
dataset_create<\/td>\n265<\/td>\n200<\/td>\n<\/tr>\n
dataset_delete<\/td>\n261<\/td>\n200<\/td>\n<\/tr>\n
dataset_delete<\/td>\n2<\/td>\n500<\/td>\n<\/tr>\n
dataset_read<\/td>\n11767<\/td>\n200<\/td>\n<\/tr>\n
dataset_read<\/td>\n9<\/td>\n400<\/td>\n<\/tr>\n
dataset_read<\/td>\n4<\/td>\n500<\/td>\n<\/tr>\n
dataset_update<\/td>\n17<\/td>\n200<\/td>\n<\/tr>\n
search<\/td>\n1393<\/td>\n200<\/td>\n<\/tr>\n
search<\/td>\n4<\/td>\n400<\/td>\n<\/tr>\n
sparql<\/td>\n693<\/td>\n200<\/td>\n<\/tr>\n
sparql<\/td>\n19<\/td>\n400<\/td>\n<\/tr>\n
sparql<\/td>\n3<\/td>\n406<\/td>\n<\/tr>\n
<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n

structWSF Instance B<\/h3>\n

The instance B has 25 datasets with about 2 312 000 instance records in it. As we can notice bellow, the average time of a query to that instance for all web service endpoints is about 550 milliseconds.<\/p>\n

Why the average query time per query double with the size of that instance? It is what we will check.<\/p>\n\n\n\n\n\n\n
<\/td>\n<\/tr>\n
Number of queries<\/strong><\/td>\nAverage time for each query in seconds<\/strong><\/td>\n<\/tr>\n
37575<\/td>\n0.556303637714566<\/td>\n<\/tr>\n
<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n

The table bellow give us the total number of queries sent to each web service endpoint with an average time for each web service. What we can notice is that the time it takes to create, delete and update records in the database management systems is related to the size of the dataset. So, what happened and is there anything we can do?<\/p>\n

Most of the queries used for this analysis come from queries sent to structWSF v.1.0a1 and v1.0a2. However, something that has a major impact on these results changed in v1.0a3 that has been released last week. The big problem with these numbers is Solr’s commit time. In version v1.0a1 and v1.0a2, a Solr commit was issued each time something was updated in the index. Commit could take up to minutes sometimes with the size of its index. Since v1.0a3, we give that choice to the system administrator: he can issue commit each time something change in the index, or setup Solr’s AutoCommit setting properly. That means that we increased the performance of these CUD endpoints by about 95%.<\/p>\n

For the SPARQL endpoint, the reason is that it is mostly exclusively used to export data from a structWSF instance. This means that big dump of RDF triples are incurred for each query, which justify the average time per query of 2.1 seconds.<\/p>\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n
<\/td>\n<\/tr>\n
Web Service<\/span><\/strong><\/td>\nNumber of queries<\/strong><\/td>\nAverage time for each query in seconds<\/strong><\/td>\n<\/tr>\n
dataset_create<\/td>\n173<\/td>\n0.09835156953404<\/td>\n<\/tr>\n
auth_registrar_access<\/td>\n1135<\/td>\n0.114255581658327<\/td>\n<\/tr>\n
dataset_update<\/td>\n121<\/td>\n0.119028852005636<\/td>\n<\/tr>\n
dataset_read<\/td>\n12683<\/td>\n0.159165935205064<\/td>\n<\/tr>\n
crud_read<\/td>\n8546<\/td>\n0.23457546435556<\/td>\n<\/tr>\n
converter\/bibtex<\/td>\n109<\/td>\n0.405608450600873<\/td>\n<\/tr>\n
auth_lister<\/td>\n2315<\/td>\n0.471687612780759<\/td>\n<\/tr>\n
search<\/td>\n2313<\/td>\n0.533951056245796<\/td>\n<\/tr>\n
browse<\/td>\n9103<\/td>\n0.758227908033767<\/td>\n<\/tr>\n
converter\/tsv<\/td>\n8<\/td>\n0.863690733909698<\/td>\n<\/tr>\n
sparql<\/td>\n650<\/td>\n2.115058046487879<\/td>\n<\/tr>\n
converter\/irv<\/td>\n166<\/td>\n2.681712512510398<\/td>\n<\/tr>\n
crud_update<\/td>\n13<\/td>\n4.649851157114154<\/td>\n<\/tr>\n
crud_create<\/td>\n75<\/td>\n11.306954870223277<\/td>\n<\/tr>\n
dataset_delete<\/td>\n140<\/td>\n27.511527856750207<\/td>\n<\/tr>\n
crud_delete<\/td>\n25<\/td>\n34.33350466727492<\/td>\n<\/tr>\n
<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n

This table gives the number of queries for each returned HTTP response status code by the endpoint.<\/p>\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n
<\/td>\n<\/tr>\n
Web Service<\/span><\/strong><\/td>\nNumber of queries<\/strong><\/td>\nHTTP Response Status<\/span><\/strong><\/td>\n<\/tr>\n
auth_lister<\/td>\n2275<\/td>\n200<\/td>\n<\/tr>\n
auth_lister<\/td>\n11<\/td>\n400<\/td>\n<\/tr>\n
auth_lister<\/td>\n2<\/td>\n406<\/td>\n<\/tr>\n
auth_lister<\/td>\n27<\/td>\n500<\/td>\n<\/tr>\n
auth_registrar_access<\/td>\n1110<\/td>\n200<\/td>\n<\/tr>\n
auth_registrar_access<\/td>\n25<\/td>\n400<\/td>\n<\/tr>\n
browse<\/td>\n9084<\/td>\n200<\/td>\n<\/tr>\n
browse<\/td>\n18<\/td>\n400<\/td>\n<\/tr>\n
browse<\/td>\n1<\/td>\n406<\/td>\n<\/tr>\n
converter\/bibtex<\/td>\n108<\/td>\n200<\/td>\n<\/tr>\n
converter\/bibtex<\/td>\n1<\/td>\n400<\/td>\n<\/tr>\n
converter\/irv<\/td>\n154<\/td>\n200<\/td>\n<\/tr>\n
converter\/irv<\/td>\n12<\/td>\n400<\/td>\n<\/tr>\n
converter\/tsv<\/td>\n8<\/td>\n200<\/td>\n<\/tr>\n
crud_create<\/td>\n41<\/td>\n200<\/td>\n<\/tr>\n
crud_create<\/td>\n33<\/td>\n400<\/td>\n<\/tr>\n
crud_create<\/td>\n1<\/td>\n500<\/td>\n<\/tr>\n
crud_delete<\/td>\n24<\/td>\n200<\/td>\n<\/tr>\n
crud_delete<\/td>\n1<\/td>\n400<\/td>\n<\/tr>\n
crud_read<\/td>\n8268<\/td>\n200<\/td>\n<\/tr>\n
crud_read<\/td>\n273<\/td>\n400<\/td>\n<\/tr>\n
crud_read<\/td>\n5<\/td>\n406<\/td>\n<\/tr>\n
crud_update<\/td>\n4<\/td>\n200<\/td>\n<\/tr>\n
crud_update<\/td>\n9<\/td>\n400<\/td>\n<\/tr>\n
dataset_create<\/td>\n171<\/td>\n200<\/td>\n<\/tr>\n
dataset_create<\/td>\n2<\/td>\n400<\/td>\n<\/tr>\n
dataset_delete<\/td>\n79<\/td>\n200<\/td>\n<\/tr>\n
dataset_delete<\/td>\n61<\/td>\n500<\/td>\n<\/tr>\n
dataset_read<\/td>\n12647<\/td>\n200<\/td>\n<\/tr>\n
dataset_read<\/td>\n11<\/td>\n400<\/td>\n<\/tr>\n
dataset_read<\/td>\n25<\/td>\n500<\/td>\n<\/tr>\n
dataset_update<\/td>\n113<\/td>\n200<\/td>\n<\/tr>\n
dataset_update<\/td>\n8<\/td>\n500<\/td>\n<\/tr>\n
search<\/td>\n2286<\/td>\n200<\/td>\n<\/tr>\n
search<\/td>\n24<\/td>\n400<\/td>\n<\/tr>\n
search<\/td>\n3<\/td>\n406<\/td>\n<\/tr>\n
sparql<\/td>\n618<\/td>\n200<\/td>\n<\/tr>\n
sparql<\/td>\n22<\/td>\n400<\/td>\n<\/tr>\n
sparql<\/td>\n6<\/td>\n406<\/td>\n<\/tr>\n
sparql<\/td>\n4<\/td>\n500<\/td>\n<\/tr>\n
<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n

Generating the Stats<\/h3>\n

Here is the list of SQL query used to create these stat tables. You can run them locally on your structWSF instance to generate the same kind of statistics.<\/p>\n

Timespan of the queries<\/p>\n

select min(request_datetime) as startdate, max(request_datetime) as enddate from SD.WSF.ws_queries_log;<\/p><\/blockquote>\n

Get the average number of milliseconds per query sent to the syste<\/p>\n

select count(request_processing_time) as nb_queries, avg(request_processing_time) as average_query_time from SD.WSF.ws_queries_log order by ID desc;<\/p><\/blockquote>\n

Get the average query time for each web service of a structWSF instance.<\/p>\n

select requested_web_service, count(request_processing_time) as nb_queries, avg(request_processing_time) as average_query_time from SD.WSF.ws_queries_log GROUP BY requested_web_service ORDER BY average_query_time ASC;<\/p><\/blockquote>\n

Status messages counts per web service endpoint<\/p>\n

select requested_web_service, count(request_http_response_status) as nb_queries, request_http_response_status from SD.WSF.ws_queries_log GROUP BY requested_web_service, request_http_response_status ORDER BY requested_web_service, request_http_response_status;<\/p><\/blockquote>\n","protected":false},"excerpt":{"rendered":"

We have been running different structWSF instances for about two months now. Each instance is hosting different dataset(s) that are queried for different purposes. I think that it worth taking some time starting to analyze the querying stats of two of these instances of the early Alpha version of structWSF. The goal is to create […]<\/p>\n","protected":false},"author":2,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"_jetpack_memberships_contains_paid_content":false,"footnotes":""},"categories":[155,153],"tags":[162,163],"class_list":["post-949","post","type-post","status-publish","format-standard","hentry","category-osf-web-services","category-structured-dynamics","tag-open-semantic-framework-2","tag-structwsf-2"],"jetpack_featured_media_url":"","jetpack_sharing_enabled":true,"_links":{"self":[{"href":"https:\/\/fgiasson.com\/blog\/index.php\/wp-json\/wp\/v2\/posts\/949","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/fgiasson.com\/blog\/index.php\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/fgiasson.com\/blog\/index.php\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/fgiasson.com\/blog\/index.php\/wp-json\/wp\/v2\/users\/2"}],"replies":[{"embeddable":true,"href":"https:\/\/fgiasson.com\/blog\/index.php\/wp-json\/wp\/v2\/comments?post=949"}],"version-history":[{"count":17,"href":"https:\/\/fgiasson.com\/blog\/index.php\/wp-json\/wp\/v2\/posts\/949\/revisions"}],"predecessor-version":[{"id":966,"href":"https:\/\/fgiasson.com\/blog\/index.php\/wp-json\/wp\/v2\/posts\/949\/revisions\/966"}],"wp:attachment":[{"href":"https:\/\/fgiasson.com\/blog\/index.php\/wp-json\/wp\/v2\/media?parent=949"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/fgiasson.com\/blog\/index.php\/wp-json\/wp\/v2\/categories?post=949"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/fgiasson.com\/blog\/index.php\/wp-json\/wp\/v2\/tags?post=949"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}