Native improved profiling

This commit is contained in:
M66B 2016-01-28 18:39:13 +01:00
parent 9968185ab0
commit b0319263f8
1 changed files with 58 additions and 111 deletions

View File

@ -36,7 +36,9 @@
#include "netguard.h" #include "netguard.h"
// #define PROFILE 1 // #define PROFILE_EVENTS 5
// #define PROFILE_UID 5
// #define PROFILE_JNI 5
// TODO TCP options // TODO TCP options
// TODO TCP fragmentation // TODO TCP fragmentation
@ -332,46 +334,31 @@ void *handle_events(void *a) {
} }
} }
// Count sessions
int udp = 0;
struct udp_session *u = udp_session;
while (u != NULL) {
udp++;
u = u->next;
}
int tcp = 0;
struct tcp_session *t = tcp_session;
while (t != NULL) {
tcp++;
t = t->next;
}
if (ready == 0) if (ready == 0)
log_android(ANDROID_LOG_DEBUG, "pselect timeout udp %d tcp %d", udp, tcp); log_android(ANDROID_LOG_DEBUG, "pselect timeout");
else { else {
log_android(ANDROID_LOG_DEBUG, "pselect udp %d tcp %d ready %d", udp, tcp, ready); log_android(ANDROID_LOG_DEBUG, "pselect ready %d", ready);
#ifdef PROFILE if (pthread_mutex_lock(&lock))
log_android(ANDROID_LOG_ERROR, "pthread_mutex_lock failed");
#ifdef PROFILE_EVENTS
struct timeval start, end; struct timeval start, end;
float mselapsed; float mselapsed;
gettimeofday(&start, NULL); gettimeofday(&start, NULL);
#endif #endif
if (pthread_mutex_lock(&lock))
log_android(ANDROID_LOG_ERROR, "pthread_mutex_lock failed");
// Check upstream // Check upstream
int error; int error;
if (check_tun(args, &rfds, &wfds, &efds) < 0) if (check_tun(args, &rfds, &wfds, &efds) < 0)
error = 1; error = 1;
else { else {
#ifdef PROFILE #ifdef PROFILE_EVENTS
gettimeofday(&end, NULL); gettimeofday(&end, NULL);
mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 + mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 +
(end.tv_usec - start.tv_usec) / 1000.0; (end.tv_usec - start.tv_usec) / 1000.0;
if (mselapsed > 1) if (mselapsed > PROFILE_EVENTS)
log_android(ANDROID_LOG_INFO, "tun %f", mselapsed); log_android(ANDROID_LOG_WARN, "tun %f", mselapsed);
gettimeofday(&start, NULL); gettimeofday(&start, NULL);
#endif #endif
@ -389,12 +376,12 @@ void *handle_events(void *a) {
if (error) if (error)
break; break;
#ifdef PROFILE #ifdef PROFILE_EVENTS
gettimeofday(&end, NULL); gettimeofday(&end, NULL);
mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 + mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 +
(end.tv_usec - start.tv_usec) / 1000.0; (end.tv_usec - start.tv_usec) / 1000.0;
if (mselapsed > 1) if (mselapsed > PROFILE_EVENTS)
log_android(ANDROID_LOG_INFO, "sockets %f", mselapsed); log_android(ANDROID_LOG_WARN, "sockets %f", mselapsed);
#endif #endif
} }
} }
@ -907,7 +894,7 @@ void handle_ip(const struct arguments *args, const uint8_t *pkt, const size_t le
int flen = 0; int flen = 0;
uint8_t *payload; uint8_t *payload;
#ifdef PROFILE #ifdef PROFILE_EVENTS
float mselapsed; float mselapsed;
struct timeval start, end; struct timeval start, end;
gettimeofday(&start, NULL); gettimeofday(&start, NULL);
@ -1055,12 +1042,12 @@ void handle_ip(const struct arguments *args, const uint8_t *pkt, const size_t le
"Packet v%d %s/%u -> %s/%u proto %d flags %s uid %d", "Packet v%d %s/%u -> %s/%u proto %d flags %s uid %d",
version, source, sport, dest, dport, protocol, flags, uid); version, source, sport, dest, dport, protocol, flags, uid);
#ifdef PROFILE #ifdef PROFILE_EVENTS
gettimeofday(&end, NULL); gettimeofday(&end, NULL);
mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 + mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 +
(end.tv_usec - start.tv_usec) / 1000.0; (end.tv_usec - start.tv_usec) / 1000.0;
if (mselapsed > 1) if (mselapsed > PROFILE_EVENTS)
log_android(ANDROID_LOG_INFO, "handle ip %f", mselapsed); log_android(ANDROID_LOG_WARN, "handle ip %f", mselapsed);
#endif #endif
// Check if allowed // Check if allowed
@ -1085,6 +1072,14 @@ void handle_ip(const struct arguments *args, const uint8_t *pkt, const size_t le
else if (protocol == IPPROTO_TCP) else if (protocol == IPPROTO_TCP)
handle_tcp(args, pkt, length, payload, uid); handle_tcp(args, pkt, length, payload, uid);
} }
#ifdef PROFILE_EVENTS
gettimeofday(&end, NULL);
mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 +
(end.tv_usec - start.tv_usec) / 1000.0;
if (mselapsed > PROFILE_EVENTS)
log_android(ANDROID_LOG_WARN, "handle protocol %f", mselapsed);
#endif
} }
int has_udp_session(const struct arguments *args, const uint8_t *pkt, const uint8_t *payload) { int has_udp_session(const struct arguments *args, const uint8_t *pkt, const uint8_t *payload) {
@ -1503,11 +1498,6 @@ jboolean handle_tcp(const struct arguments *args,
const uint8_t *pkt, size_t length, const uint8_t *pkt, size_t length,
const uint8_t *payload, const uint8_t *payload,
int uid) { int uid) {
#ifdef PROFILE
float mselapsed;
struct timeval start, end;
gettimeofday(&start, NULL);
#endif
// Get headers // Get headers
const uint8_t version = (*pkt) >> 4; const uint8_t version = (*pkt) >> 4;
const struct iphdr *ip4 = (struct iphdr *) pkt; const struct iphdr *ip4 = (struct iphdr *) pkt;
@ -1627,14 +1617,6 @@ jboolean handle_tcp(const struct arguments *args,
return 0; return 0;
} }
#ifdef PROFILE
gettimeofday(&end, NULL);
mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 +
(end.tv_usec - start.tv_usec) / 1000.0;
if (mselapsed > 1)
log_android(ANDROID_LOG_INFO, "new session %f", mselapsed);
#endif
} }
else { else {
// Session found // Session found
@ -1845,14 +1827,6 @@ jboolean handle_tcp(const struct arguments *args,
cur->remote_seq - cur->remote_start, cur->remote_seq - cur->remote_start,
ntohs(tcphdr->window)); ntohs(tcphdr->window));
} }
#ifdef PROFILE
gettimeofday(&end, NULL);
mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 +
(end.tv_usec - start.tv_usec) / 1000.0;
if (mselapsed > 1)
log_android(ANDROID_LOG_INFO, "existing session %f", mselapsed);
#endif
} }
return 1; return 1;
@ -2000,12 +1974,6 @@ void write_rst(const struct arguments *args, struct tcp_session *cur) {
ssize_t write_udp(const struct arguments *args, const struct udp_session *cur, ssize_t write_udp(const struct arguments *args, const struct udp_session *cur,
uint8_t *data, size_t datalen) { uint8_t *data, size_t datalen) {
#ifdef PROFILE
float mselapsed;
struct timeval start, end;
gettimeofday(&start, NULL);
#endif
size_t len; size_t len;
u_int8_t *buffer; u_int8_t *buffer;
struct udphdr *udp; struct udphdr *udp;
@ -2097,14 +2065,7 @@ ssize_t write_udp(const struct arguments *args, const struct udp_session *cur,
ssize_t res = write(args->tun, buffer, len); ssize_t res = write(args->tun, buffer, len);
#ifdef PROFILE // Write PCAP record
gettimeofday(&end, NULL);
mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 +
(end.tv_usec - start.tv_usec) / 1000.0;
if (mselapsed > 1)
log_android(ANDROID_LOG_INFO, "tun UDP write %f", mselapsed);
#endif
if (res >= 0) { if (res >= 0) {
if (pcap_file != NULL) if (pcap_file != NULL)
write_pcap_rec(buffer, res); write_pcap_rec(buffer, res);
@ -2125,12 +2086,6 @@ ssize_t write_udp(const struct arguments *args, const struct udp_session *cur,
ssize_t write_tcp(const struct arguments *args, const struct tcp_session *cur, ssize_t write_tcp(const struct arguments *args, const struct tcp_session *cur,
const uint8_t *data, size_t datalen, size_t confirm, const uint8_t *data, size_t datalen, size_t confirm,
int syn, int ack, int fin, int rst) { int syn, int ack, int fin, int rst) {
#ifdef PROFILE
float mselapsed;
struct timeval start, end;
gettimeofday(&start, NULL);
#endif
size_t len; size_t len;
u_int8_t *buffer; u_int8_t *buffer;
struct tcphdr *tcp; struct tcphdr *tcp;
@ -2239,14 +2194,6 @@ ssize_t write_tcp(const struct arguments *args, const struct tcp_session *cur,
ssize_t res = write(args->tun, buffer, len); ssize_t res = write(args->tun, buffer, len);
#ifdef PROFILE
gettimeofday(&end, NULL);
mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 +
(end.tv_usec - start.tv_usec) / 1000.0;
if (mselapsed > 1)
log_android(ANDROID_LOG_INFO, "tun TCP write %f", mselapsed);
#endif
// Write pcap record // Write pcap record
if (res >= 0) { if (res >= 0) {
if (pcap_file != NULL) if (pcap_file != NULL)
@ -2293,7 +2240,7 @@ jint get_uid(const int protocol, const int version,
int port; int port;
jint uid = -1; jint uid = -1;
#ifdef PROFILE #ifdef PROFILE_UID
float mselapsed; float mselapsed;
struct timeval start, end; struct timeval start, end;
gettimeofday(&start, NULL); gettimeofday(&start, NULL);
@ -2366,12 +2313,12 @@ jint get_uid(const int protocol, const int version,
if (fclose(fd)) if (fclose(fd))
log_android(ANDROID_LOG_ERROR, "fclose %s error %d: %s", fn, errno, strerror(errno)); log_android(ANDROID_LOG_ERROR, "fclose %s error %d: %s", fn, errno, strerror(errno));
#ifdef PROFILE #ifdef PROFILE_UID
gettimeofday(&end, NULL); gettimeofday(&end, NULL);
mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 + mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 +
(end.tv_usec - start.tv_usec) / 1000.0; (end.tv_usec - start.tv_usec) / 1000.0;
if (mselapsed > 1) if (mselapsed > PROFILE_UID)
log_android(ANDROID_LOG_INFO, "get uid ip %f", mselapsed); log_android(ANDROID_LOG_WARN, "get uid ip %f", mselapsed);
#endif #endif
return uid; return uid;
@ -2503,7 +2450,7 @@ void log_android(int prio, const char *fmt, ...) {
static jmethodID midLogPacket = NULL; static jmethodID midLogPacket = NULL;
void log_packet(const struct arguments *args, jobject jpacket) { void log_packet(const struct arguments *args, jobject jpacket) {
#ifdef PROFILE #ifdef PROFILE_JNI
float mselapsed; float mselapsed;
struct timeval start, end; struct timeval start, end;
gettimeofday(&start, NULL); gettimeofday(&start, NULL);
@ -2521,19 +2468,19 @@ void log_packet(const struct arguments *args, jobject jpacket) {
(*args->env)->DeleteLocalRef(args->env, jpacket); (*args->env)->DeleteLocalRef(args->env, jpacket);
(*args->env)->DeleteLocalRef(args->env, clsService); (*args->env)->DeleteLocalRef(args->env, clsService);
#ifdef PROFILE #ifdef PROFILE_JNI
gettimeofday(&end, NULL); gettimeofday(&end, NULL);
mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 + mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 +
(end.tv_usec - start.tv_usec) / 1000.0; (end.tv_usec - start.tv_usec) / 1000.0;
if (mselapsed > 1) if (mselapsed > PROFILE_JNI)
log_android(ANDROID_LOG_INFO, "log_packet %f", mselapsed); log_android(ANDROID_LOG_WARN, "log_packet %f", mselapsed);
#endif #endif
} }
static jmethodID midIsDomainBlocked = NULL; static jmethodID midIsDomainBlocked = NULL;
jboolean is_domain_blocked(const struct arguments *args, const char *name) { jboolean is_domain_blocked(const struct arguments *args, const char *name) {
#ifdef PROFILE #ifdef PROFILE_JNI
float mselapsed; float mselapsed;
struct timeval start, end; struct timeval start, end;
gettimeofday(&start, NULL); gettimeofday(&start, NULL);
@ -2554,12 +2501,12 @@ jboolean is_domain_blocked(const struct arguments *args, const char *name) {
(*args->env)->DeleteLocalRef(args->env, jname); (*args->env)->DeleteLocalRef(args->env, jname);
(*args->env)->DeleteLocalRef(args->env, clsService); (*args->env)->DeleteLocalRef(args->env, clsService);
#ifdef PROFILE #ifdef PROFILE_JNI
gettimeofday(&end, NULL); gettimeofday(&end, NULL);
mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 + mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 +
(end.tv_usec - start.tv_usec) / 1000.0; (end.tv_usec - start.tv_usec) / 1000.0;
if (mselapsed > 1) if (mselapsed > PROFILE_JNI)
log_android(ANDROID_LOG_INFO, "is_domain_blocked %f", mselapsed); log_android(ANDROID_LOG_WARN, "is_domain_blocked %f", mselapsed);
#endif #endif
return jallowed; return jallowed;
@ -2568,7 +2515,7 @@ jboolean is_domain_blocked(const struct arguments *args, const char *name) {
static jmethodID midIsAddressAllowed = NULL; static jmethodID midIsAddressAllowed = NULL;
jboolean is_address_allowed(const struct arguments *args, jobject jpacket) { jboolean is_address_allowed(const struct arguments *args, jobject jpacket) {
#ifdef PROFILE #ifdef PROFILE_JNI
float mselapsed; float mselapsed;
struct timeval start, end; struct timeval start, end;
gettimeofday(&start, NULL); gettimeofday(&start, NULL);
@ -2587,12 +2534,12 @@ jboolean is_address_allowed(const struct arguments *args, jobject jpacket) {
(*args->env)->DeleteLocalRef(args->env, jpacket); (*args->env)->DeleteLocalRef(args->env, jpacket);
(*args->env)->DeleteLocalRef(args->env, clsService); (*args->env)->DeleteLocalRef(args->env, clsService);
#ifdef PROFILE #ifdef PROFILE_JNI
gettimeofday(&end, NULL); gettimeofday(&end, NULL);
mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 + mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 +
(end.tv_usec - start.tv_usec) / 1000.0; (end.tv_usec - start.tv_usec) / 1000.0;
if (mselapsed > 1) if (mselapsed > PROFILE_JNI)
log_android(ANDROID_LOG_INFO, "is_address_allowed %f", mselapsed); log_android(ANDROID_LOG_WARN, "is_address_allowed %f", mselapsed);
#endif #endif
return jallowed; return jallowed;
@ -2625,6 +2572,12 @@ jobject create_packet(const struct arguments *args,
jboolean allowed) { jboolean allowed) {
JNIEnv *env = args->env; JNIEnv *env = args->env;
#ifdef PROFILE_JNI
float mselapsed;
struct timeval start, end;
gettimeofday(&start, NULL);
#endif
const char *packet = "eu/faircode/netguard/Packet"; const char *packet = "eu/faircode/netguard/Packet";
if (midInitPacket == NULL) if (midInitPacket == NULL)
midInitPacket = jniGetMethodID(env, clsPacket, "<init>", "()V"); midInitPacket = jniGetMethodID(env, clsPacket, "<init>", "()V");
@ -2671,6 +2624,14 @@ jobject create_packet(const struct arguments *args,
(*env)->DeleteLocalRef(env, jflags); (*env)->DeleteLocalRef(env, jflags);
// Caller needs to delete reference to packet // Caller needs to delete reference to packet
#ifdef PROFILE_JNI
gettimeofday(&end, NULL);
mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 +
(end.tv_usec - start.tv_usec) / 1000.0;
if (mselapsed > PROFILE_JNI)
log_android(ANDROID_LOG_WARN, "create_packet %f", mselapsed);
#endif
return jpacket; return jpacket;
} }
@ -2704,12 +2665,6 @@ void write_pcap_rec(const uint8_t *buffer, size_t length) {
} }
void write_pcap(const void *ptr, size_t len) { void write_pcap(const void *ptr, size_t len) {
#ifdef PROFILE
float mselapsed;
struct timeval start, end;
gettimeofday(&start, NULL);
#endif
if (fwrite(ptr, len, 1, pcap_file) < 1) if (fwrite(ptr, len, 1, pcap_file) < 1)
log_android(ANDROID_LOG_ERROR, "PCAP fwrite error %d: %s", errno, strerror(errno)); log_android(ANDROID_LOG_ERROR, "PCAP fwrite error %d: %s", errno, strerror(errno));
else { else {
@ -2728,14 +2683,6 @@ void write_pcap(const void *ptr, size_t len) {
} }
} }
} }
#ifdef PROFILE
gettimeofday(&end, NULL);
mselapsed = (end.tv_sec - start.tv_sec) * 1000.0 +
(end.tv_usec - start.tv_usec) / 1000.0;
if (mselapsed > 1)
log_android(ANDROID_LOG_INFO, "pcap write %f", mselapsed);
#endif
} }
char *trim(char *str) { char *trim(char *str) {