ServiceStack
zorlack
—
2017-05-12T13:23:34Z —
#1
Hello,
I'm seeing a performance issue which I can't figure out.
I have an API endpoint which returns data from a OrmLite query.
When I request the page without any "Accept" header the page performs extremely well.
M:\>curl -w "@curl-format.txt" "http://localhost:18088/api/broadcast/stations" -H "Cookie: ss-id=PZgbO14exQKkQF72Fs3l; ss-pid=HAyYGBgA1pK6E7eMMGSH; ss-opt=temp; X-UAId=1" -o NUL
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 288k 0 288k 0 0 4659k 0 --:--:-- --:--:-- --:--:-- 4659k
time_namelookup: 0.000000
time_connect: 0.000000
time_appconnect: 0.000000
time_pretransfer: 0.015000
time_redirect: 0.000000
time_starttransfer: 0.062000
----------
time_total: 0.062000
Here you can see that we downloaded 288KB from localhost in 62ms. There are no razor templates at play here, so the resulting HTML is the default ServiceStack data renderer which appears itself to be based on the JSON data.
When I go to test the performance of endpoint using Accept: application/json performance is significantly degraded:
M:\>curl -w "@curl-format.txt" "http://localhost:18088/api/broadcast/stations" -H "Cookie: ss-id=PZgbO14exQKkQF72Fs3l; ss-pid=HAyYGBgA1pK6E7eMMGSH; ss-opt=temp; X-UAId=1" -H "Accept: application/json" -o out.txt
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 279k 0 279k 0 0 119k 0 --:--:-- 0:00:02 --:--:-- 119k
time_namelookup: 0.000000
time_connect: 0.000000
time_appconnect: 0.000000
time_pretransfer: 0.000000
time_redirect: 0.000000
time_starttransfer: 0.047000
----------
time_total: 2.344000
Here you can see that despite returning slightly less data (because no HTML is included) the query took more than 2000ms.
I don't think this is related to any kind of caching because the discrepancy is consistent even right after startup.
This feels to me like it may be a routing problem or something, but I'm not at all sure where to look.
The Service Model looks like this:
namespace ServiceStackWithFrontend.ServiceModel
{
[Route("/api/broadcast/stations")]
public class GetStations : IReturn<StationListResponse>
{
}
public class StationListResponse
{
public List<Station> Stations { get; set; }
}
}
And the service itself looks like this:
public class BroadcastService : Service
{
private readonly IDbConnectionFactory dbFactory;
public BroadcastService(IDbConnectionFactory factory)
{
this.dbFactory = factory;
}
[Authenticate]
public Object Get(GetStations request)
{
StationListResponse response = new StationListResponse();
using (var db = dbFactory.OpenDbConnection())
{
response.Stations = db.Select<Station>(s => s.Active == 1);
}
return response;
}
}
It's being manually registered in the App using this:
container.Register(new BroadcastService(new OrmLiteConnectionFactory(container.Resolve<IAppSettings>().GetString("OrmLiteMMSConnectionString"), SqlServerDialect.Provider)));
Any idea why there would be such a significant performance discrepancy?
zorlack
—
2017-05-12T13:42:47Z —
#2
In diving in a bit deeper here, I'm starting to think this may be cache related.
When I change the service to include a CacheResponse attribute like this:
[CacheResponse(CacheControl=CacheControl.NoCache)]
public class BroadcastService : Service
{
private readonly IDbConnectionFactory dbFactory;
public BroadcastService(IDbConnectionFactory factory)
{
this.dbFactory = factory;
}
[Authenticate]
public Object Get(GetStations request)
{
StationListResponse response = new StationListResponse();
using (var db = dbFactory.OpenDbConnection())
{
response.Stations = db.Select<Station>(s => s.Active == 1);
}
return response;
}
}
The performance discrepancy goes away.
EDIT: This might be irrelevant. Since I think all I've accomplished here is to turn on caching and send a no-cache header.
mythz
—
2017-05-12T13:59:51Z —
#3
No idea why you'd see a penalty with an application/json
response, does the penalty still exist when you request a JSON response without using the Accept header, i.e:
/api/broadcast/stations.json
/api/broadcast/stations?format=json
mythz
—
2017-05-12T14:12:56Z —
#4
BTW is there any reason you're not using the built in base.Db
property? i.e:
public object Get(GetStations request) =>
new StationListResponse {
Stations = Db.Select<Station>(s => s.Active == 1)
};
zorlack
—
2017-05-12T14:16:55Z —
#5
Yes, the discrepancy is still there.
To simplify the test I've removed the Authenticate requirement and performed each CURL test after a fresh restart of the application.
The results similar.
Here's the request for the HTML version
M:\>curl -w "@curl-format.txt" "http://localhost:18088/api/broadcast/stations" -o out.txt
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 288k 0 288k 0 0 410k 0 --:--:-- --:--:-- --:--:-- 410k
time_namelookup: 0.000000
time_connect: 0.000000
time_appconnect: 0.000000
time_pretransfer: 0.000000
time_redirect: 0.000000
time_starttransfer: 0.688000
----------
time_total: 0.703000
Here's the request with the JSON version.
M:\>curl -w "@curl-format.txt" "http://localhost:18088/api/broadcast/stations?format=json" -o out.txt
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 279k 0 279k 0 0 80396 0 --:--:-- 0:00:03 --:--:-- 80396
time_namelookup: 0.000000
time_connect: 0.000000
time_appconnect: 0.000000
time_pretransfer: 0.000000
time_redirect: 0.000000
time_starttransfer: 0.375000
----------
time_total: 3.562000
Another factor could be that I'm running this as a Stand-Alone application.
Here's our AppHost.Configure:
public override void Configure(Container container)
{
SetConfig(new HostConfig
{
WebHostPhysicalPath = "client-side"
});
container.Register<IAppSettings>(new AppSettings());
container.Register<IDbConnectionFactory>(c => new OrmLiteConnectionFactory(container.Resolve<IAppSettings>().GetString("OrmLiteConnectionString"), SqliteDialect.Provider)); //InMemory Sqlite DB
container.Register<ICacheClient>(new MemoryCacheClient());
container.Register<IUserAuthRepository>(new OrmLiteAuthRepository(container.Resolve<IDbConnectionFactory>()));
container.Register(new BroadcastService(new OrmLiteConnectionFactory(container.Resolve<IAppSettings>().GetString("OrmLiteMMSConnectionString"), SqlServerDialect.Provider)));
ValidateAuthenticationScheme(container);
this.Plugins.Add(new AuthFeature(() => new AuthUserSession(),
new IAuthProvider[] {
new CredentialsAuthProvider(),
},
"/#login")
);
this.Plugins.Add(new AdminFeature());
this.Plugins.Add(new AutoQueryFeature { MaxLimit = 100 });
this.Plugins.Add(new RegistrationFeature());
this.Plugins.Add(new PostmanFeature());
this.Plugins.Add(new CorsFeature());
this.GlobalResponseFilters.Add((request, response, responseDto) =>
{
if (response.Dto != null && response.Dto.GetType() == typeof(AuthenticateResponse))
{
((AuthenticateResponse)response.Dto).Meta = new Dictionary<string, string>();
((AuthenticateResponse)response.Dto).Meta["Roles"] = request.GetSession().Roles.ToJson();
}
});
}
The reason for the Database connection weirdness is that I'm using OrmLite to connect to two distinct database services. One specifically for this service.
mythz
—
2017-05-12T14:23:25Z —
#6
that's really strange, the html should be using the same JSON serialization but embedded in a HTML page.
Can you confirm that the html version that's returned also includes the same json in:
var model = {JSON},
zorlack
—
2017-05-12T14:32:07Z —
#7
Yes, the HTML version uses the exact same JSON blob as is produced by format=json. (Same exact byte count)
I added a little bit of debug logging and have confirmed that the query portion of the code is consistently fast. The delay seems to occur after I return the response from the Get function.
mythz
—
2017-05-12T14:48:33Z —
#8
Could you do some profiling (e.g dotTrace has a free demo period) so we can workout where the time is being spent? Otherwise we'd need a stand-alone repro we could investigate ourselves.
zorlack
—
2017-05-12T15:31:27Z —
#9
I'm not very familiar with dotTrace, but here's what I see.
First: The Request.
M:\>curl -w "@curl-format.txt" "http://localhost:18088/api/broadcast/stations?format=json" -o out.txt
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 279k 0 279k 0 0 56573 0 --:--:-- 0:00:05 --:--:-- 62134
time_namelookup: 0.015000
time_connect: 0.015000
time_appconnect: 0.000000
time_pretransfer: 0.015000
time_redirect: 0.000000
time_starttransfer: 0.296000
----------
time_total: 5.062000
The HTTP request portion of the call seems to perform relatively quickly (280ms):
When I back up and look at a broader context I see that most of the time is being spent in ServiceStack.Text.Common.WriteListsOfElements:
Could this be something to do with my Station POCO? It looks like this:
[Alias("Stations")]
public class Station
{
public int StationID { get; set; }
[Alias("UniqueIdentifier")]
public string StationGUID { get;set;}
public string StationName { get; set; }
[Alias("MarketID")]
public int MarketId { get; set; }
public short MediaType { get; set; }
public short Active { get; set; }
public string NationalNetwork { get; set; }
}
Many thanks!
-Z
mythz
—
2017-05-12T15:36:09Z —
#10
Doesn't look like it should, but I'll check. Can you confirm these are all the DTO classes used in that service?
[Route("/api/broadcast/stations")]
public class GetStations : IReturn<StationListResponse>
{
}
public class StationListResponse
{
public List<Station> Stations { get; set; }
}
[Alias("Stations")]
public class Station
{
public int StationID { get; set; }
[Alias("UniqueIdentifier")]
public string StationGUID { get;set;}
public string StationName { get; set; }
[Alias("MarketID")]
public int MarketId { get; set; }
public short MediaType { get; set; }
public short Active { get; set; }
public string NationalNetwork { get; set; }
}
zorlack
—
2017-05-12T15:36:12Z —
#11
Here's what the HTML request looks like.
M:\>curl -w "@curl-format.txt" "http://localhost:18088/api/broadcast/stations" -o out.txt
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 288k 0 288k 0 0 802k 0 --:--:-- --:--:-- --:--:-- 802k
time_namelookup: 0.016000
time_connect: 0.016000
time_appconnect: 0.000000
time_pretransfer: 0.016000
time_redirect: 0.000000
time_starttransfer: 0.329000
----------
time_total: 0.360000
Note that HandleResponse looks very different in this call:
zorlack
—
2017-05-12T15:42:29Z —
#12
Here's the complete service:
public class BroadcastService : Service
{
private readonly IDbConnectionFactory dbFactory;
public static ILog Log = LogManager.GetLogger(typeof(BroadcastService));
public BroadcastService(IDbConnectionFactory factory)
{
this.dbFactory = factory;
}
public Object Get(GetStations request)
{
StationListResponse response = new StationListResponse();
using (var db = dbFactory.OpenDbConnection())
{
response.Stations = db.Select<Station>(s => s.Active == 1);
}
Log.Debug("Query Complete.");
return response;
}
public Object Get(GetMarkets request)
{
MarketListResponse response = new MarketListResponse();
using (var db = dbFactory.OpenDbConnection())
{
response.Markets = db.LoadSelect<Market>(m => m.Active == true);
}
return response;
}
public Object Get(GetCountries request)
{
CountryListResponse response = new CountryListResponse();
response.Countries = new List<Country>();
List<Market> marketList = new List<Market>();
using (var db = dbFactory.OpenDbConnection())
{
marketList = db.LoadSelect<Market>(m => m.Active == true);
}
foreach(String countryCode in marketList.Select(m => m.Country).Distinct().ToList())
{
List<State> countryStates = new List<State>();
foreach(String state in marketList.Where(m => m.Country == countryCode && m.State != null && m.State.Length > 0).Select(m => m.State).Distinct().ToList())
{
countryStates.Add(new State { StateCode = state, Markets = marketList.Where(m => m.Country == countryCode && m.State == state).ToList() });
}
var country = new Country
{
CountryCode = countryCode,
Markets = marketList.Where(m => m.Country == countryCode && (m.State == null || m.State.Trim().Length == 0)).ToList(),
States = countryStates
};
response.Countries.Add(country);
}
return response;
}
}
Here are the Underlying classes:
[Alias("Stations")]
public class Station
{
public int StationID { get; set; }
[Alias("UniqueIdentifier")]
public string StationGUID { get;set;}
public string StationName { get; set; }
[Alias("MarketID")]
public int MarketId { get; set; }
public short MediaType { get; set; }
public short Active { get; set; }
public string NationalNetwork { get; set; }
}
public class Market
{
public int MarketID { get; set; }
public string MarketName { get; set; }
public string Country { get; set; }
public bool Active { get; set; }
//public int? FilterOrder { get; set; }
//public string DefaultAccess { get; set; }
public string State { get; set; }
public string Latitude { get; set; }
public string Longitude { get; set; }
public int? DMARank { get; set; }
[Reference]
public List<Station> Stations { get; set; }
}
public class Country
{
public String CountryCode { get; set; }
public List<State> States { get; set; }
public List<Market> Markets { get; set; }
}
public class State
{
public String StateCode { get; set; }
public List<Market> Markets { get; set; }
}
Here is the Service Model:
[Route("/api/broadcast/stations")]
public class GetStations : IReturn<StationListResponse>
{
}
public class StationListResponse
{
public List<Station> Stations { get; set; }
}
[Route("/api/broadcast/markets")]
public class GetMarkets : IReturn<MarketListResponse>
{
}
public class MarketListResponse
{
public List<Market> Markets { get; set; }
}
[Route("/api/broadcast/countries")]
public class GetCountries : IReturn<CountryListResponse>
{
}
public class CountryListResponse
{
public List<Country> Countries { get; set; }
}
xplicit
—
2017-05-12T16:07:18Z —
#13
@zorlack How many elements of Station
are returned by your service? If the record is small in length and number of records is large then performance degradation could be caused by auto-flushing when response uses chunked encoding. Need to confirm that this is your case to make a fix for it.
zorlack
—
2017-05-12T16:28:07Z —
#14
The query should be returning about 3,000 results - so quite a large dataset. However, the same sized data set is being returned via the Default HTML handler. (Not sure if that's relevant or not)
One other thing to note, I've now added a search parameter to my service which lets me restrict the list of content being returned. Here's a a test which only returns 3 results:
Default HTML Handler (After a fresh start):
M:\>curl -w "@curl-format.txt" "http://localhost:18088/api/broadcast/stations?search=CSPAN" -o out.txt
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 9924 0 9924 0 0 57697 0 --:--:-- --:--:-- --:--:-- 57697
time_namelookup: 0.016000
time_connect: 0.016000
time_appconnect: 0.000000
time_pretransfer: 0.016000
time_redirect: 0.000000
time_starttransfer: 0.172000
----------
time_total: 0.172000
Format=JSON request for the same content (After a fresh start):
M:\>curl -w "@curl-format.txt" "http://localhost:18088/api/broadcast/stations?search=CSPAN&format=json" -o out.txt
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 382 0 382 0 0 1632 0 --:--:-- --:--:-- --:--:-- 1632
time_namelookup: 0.000000
time_connect: 0.000000
time_appconnect: 0.000000
time_pretransfer: 0.000000
time_redirect: 0.000000
time_starttransfer: 0.219000
----------
time_total: 0.234000
After repeatedly hammering this interface, it seems that small results sets return in roughly the same amount of time regardless of whether the content comes from the HTML handler or the JSON handler.
I suspect you may be right that this is related to chunking or some other transmission-related function.
zorlack
—
2017-05-12T16:51:27Z —
#15
We've been doing a bit of Wireshark testing and I do think that this is due to Chunked-Encoding.
When requesting the HTML version of the page we see that data is sent in 2 chunks
However, when requesting the raw JSON for the same content I see the data sent in over 6,000 tiny chunks:
I think this confirms your suspicions.
xplicit
—
2017-05-12T16:58:01Z —
#16
@zorlack I just pushed the change to MyGet which should resolve the issue with chunked encoding. Can you check the latest v4.5.9 from MyGet and tell does it help in your case?
zorlack
—
2017-05-12T18:03:33Z —
#17
@xplicit That seems to have done it. I now see we're creating far-fewer TCP segments when requesting JSON content.
For reference, our latest HTML test returned 27,128KB over 4 packets.
M:\>curl -w "@curl-format.txt" "http://localhost:18088/api/broadcast/markets?search=new" -o out.txt
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 26763 0 26763 0 0 104k 0 --:--:-- --:--:-- --:--:-- 104k
time_namelookup: 0.000000
time_connect: 0.000000
time_appconnect: 0.000000
time_pretransfer: 0.000000
time_redirect: 0.000000
time_starttransfer: 0.250000
----------
time_total: 0.250000
The JSON test returned 17,739KB over 18 packets. The new packets are larger than 1000B (instead of being around 60B).
M:\>curl -w "@curl-format.txt" "http://localhost:18088/api/broadcast/markets?search=new&format=json" -o out.txt
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 17241 0 17241 0 0 27585 0 --:--:-- --:--:-- --:--:-- 27585
time_namelookup: 0.000000
time_connect: 0.000000
time_appconnect: 0.000000
time_pretransfer: 0.000000
time_redirect: 0.000000
time_starttransfer: 0.609000
----------
time_total: 0.625000
These examples are first-requests. Subsequent requests are significantly faster and HTML/JSON now compare favorably.
Many thanks for looking into this!
-Z
xplicit
—
2017-05-12T18:58:33Z —
#18
It's interesting that returning data in 4 big packets gets significant less time than returning data in 18 * 1K blocks. If this is not measurement fluctuation that means the buffer for chunked encoding should be larger than default buffer of 1024 bytes.
zorlack
—
2017-05-12T19:22:30Z —
#19
Is that buffer size user-configurable or is that a hard-coded thing?
xplicit
—
2017-05-12T19:36:17Z —
#20
This size of buffer is used in .NET StreamWriter
implementation. It cannot be changed directly in user code.
next page →